Thrift
  1. Thrift
  2. THRIFT-638

BufferedTransport + C extensions block until recv timeout is reached on last fread call

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.2
    • Fix Version/s: 0.7
    • Component/s: PHP - Library
    • Labels:
      None

      Description

      I wanted to throw this out if any other folks experience this later on. At Digg we've been using the BufferedTransport + C extension of Thrift in PHP. Every so often, we will see spikes in latency increases on RPC calls that we know have acceptable response times (<200ms). This seems to happen based on how much data is being sent back over the wire. This is more of a PHP problem, but can be corrected in Thrift's PHP library for folks who don't want to upgrade PHP. I am still waiting to see if it's corrected in later versions (we use 5.2.9).

      http://bonsai.php.net/bug.php?id=42720

      Replacing the fread statements in TSocket.php with stream_socket_recvfrom correct this behavior so that calls do not wait until they hit the recv timeout.

      1. 0001-Replace-freads-with-stream_socket_recvfrom.patch
        1 kB
        Chris Goffinet
      2. 0002-tocket-read-meta-data-check.diff
        0.7 kB
        Arya Goudarzi
      3. thrift-tsocket-638.patch
        3 kB
        Nicholas Telford
      4. thrift-tsocket-638-0002.patch
        4 kB
        Nicholas Telford
      5. thrift-tsocket-638-0003.patch
        8 kB
        Nicholas Telford

        Issue Links

          Activity

          Hide
          Bryan Duxbury added a comment -

          I just committed this. Thanks for the patch, Nicholas!

          Show
          Bryan Duxbury added a comment - I just committed this. Thanks for the patch, Nicholas!
          Hide
          Nicholas Telford added a comment -

          Unless anyone has any objections, I'd say so.

          Show
          Nicholas Telford added a comment - Unless anyone has any objections, I'd say so.
          Hide
          Tyler Hobbs added a comment -

          Yes, I think so.

          Show
          Tyler Hobbs added a comment - Yes, I think so.
          Hide
          Bryan Duxbury added a comment -

          So are we ready for a commit guys?

          Show
          Bryan Duxbury added a comment - So are we ready for a commit guys?
          Hide
          Nicholas Telford added a comment -

          Excellent! No worries Tyler, it forced me to test my changed more aggressively and it's additional testing spent on phpcassa. Neither of which can be a bad thing!

          Show
          Nicholas Telford added a comment - Excellent! No worries Tyler, it forced me to test my changed more aggressively and it's additional testing spent on phpcassa. Neither of which can be a bad thing!
          Hide
          Tyler Hobbs added a comment -

          Hi Nicholas,

          You're correct – it was discovered yesterday that the master branch of phpcassa was setting a default timeout of 1 millisecond. After correcting this, I'm no longer able to reproduce the problem. I think you've solved the issue!

          Thanks for your hard work, and sorry about any extra time I made you spend looking through this.

          Show
          Tyler Hobbs added a comment - Hi Nicholas, You're correct – it was discovered yesterday that the master branch of phpcassa was setting a default timeout of 1 millisecond. After correcting this, I'm no longer able to reproduce the problem. I think you've solved the issue! Thanks for your hard work, and sorry about any extra time I made you spend looking through this.
          Hide
          Nicholas Telford added a comment -

          Hi Tyler,

          I've been working to reproduce the issues you're seeing using phpcassa and cassandra. I noticed that phpcassa sets the default timeouts (send and recv) to 1 millisecond. I imagine this was meant to be in seconds as 1 millisecond seems rather optimistic!

          In my tests I set my timeouts to 10 seconds (the VM I'm testing on was swapping badly so Cassandra needed some time to GC a lot) and could not reproduce those problems.

          I did notice that your tests take a very long time and a ton of CPU to run, strace reveals that gettimeofday() is being called nearly constantly (approximately every 200 microseconds). I don't think this is related so I haven't gone in to too much detail looking for the culprit there, but I'm pretty certain it's not Thrift.

          If it's not too much trouble an EC2 instance would help a great deal in tracking this down.

          Show
          Nicholas Telford added a comment - Hi Tyler, I've been working to reproduce the issues you're seeing using phpcassa and cassandra. I noticed that phpcassa sets the default timeouts (send and recv) to 1 millisecond. I imagine this was meant to be in seconds as 1 millisecond seems rather optimistic! In my tests I set my timeouts to 10 seconds (the VM I'm testing on was swapping badly so Cassandra needed some time to GC a lot) and could not reproduce those problems. I did notice that your tests take a very long time and a ton of CPU to run, strace reveals that gettimeofday() is being called nearly constantly (approximately every 200 microseconds). I don't think this is related so I haven't gone in to too much detail looking for the culprit there, but I'm pretty certain it's not Thrift. If it's not too much trouble an EC2 instance would help a great deal in tracking this down.
          Hide
          Tyler Hobbs added a comment -

          Without the patch from THRIFT-867, I still see 'TSocket: Could not read 4 bytes' immediately. (Note that I also ran tests without the C extension at all and experienced the occasional 'Could not read 4 bytes' behavior.)

          I was not using a timeout, but I tested again setting send and recv timeouts to 10000 (ten seconds), and behavior was the same. Cassandra isn't logging any failure messages, and the test should be well below what Cassandra can handle easily.

          I'm not sure I could give you any more specifics to help reproduce other than setting up an environment for you. Would an EC2 instance that's ready to go with phpcassa be useful?

          I'm glad PHP performance might finally be up to par!

          Show
          Tyler Hobbs added a comment - Without the patch from THRIFT-867 , I still see 'TSocket: Could not read 4 bytes' immediately. (Note that I also ran tests without the C extension at all and experienced the occasional 'Could not read 4 bytes' behavior.) I was not using a timeout, but I tested again setting send and recv timeouts to 10000 (ten seconds), and behavior was the same. Cassandra isn't logging any failure messages, and the test should be well below what Cassandra can handle easily. I'm not sure I could give you any more specifics to help reproduce other than setting up an environment for you. Would an EC2 instance that's ready to go with phpcassa be useful? I'm glad PHP performance might finally be up to par!
          Hide
          Nicholas Telford added a comment -

          Tyler, I did test with the TFramedTransport, although it's possible I missed something. A few questions:

          • Is this with the patch(es) from THRIFT-867 applied?
          • What timeout are you using? Is it possible that the Cassandra node is taking a long time to complete the operation or failing altogether?

          Assuming your answers still indicate a problem, I'll work to reproduce this tomorrow. If you have any other information that will help me reproduce it, that'd be great

          FWIW, the "quite a bit faster" is actually the expected behaviour of Thrift. The bug was causing incredibly poor performance.

          Show
          Nicholas Telford added a comment - Tyler, I did test with the TFramedTransport, although it's possible I missed something. A few questions: Is this with the patch(es) from THRIFT-867 applied? What timeout are you using? Is it possible that the Cassandra node is taking a long time to complete the operation or failing altogether? Assuming your answers still indicate a problem, I'll work to reproduce this tomorrow. If you have any other information that will help me reproduce it, that'd be great FWIW, the "quite a bit faster" is actually the expected behaviour of Thrift. The bug was causing incredibly poor performance.
          Hide
          Tyler Hobbs added a comment -

          The the 003 version of the patch, I'm seeing better behavior, but still occasional problems.

          With or without the C extension, using TFramedTransport, I get 'TSocket: timed out reading 4 bytes' about 25% of the time when running this test (requires Cassandra):

          https://github.com/thobbs/phpcassa/blob/master/test/test_large_ops.php

          The patched version of this does run quite a bit faster, so that's a nice bonus. Thanks for the hard work, Nicholas! Hopefully we can get to the bottom of this.

          Show
          Tyler Hobbs added a comment - The the 003 version of the patch, I'm seeing better behavior, but still occasional problems. With or without the C extension, using TFramedTransport, I get 'TSocket: timed out reading 4 bytes' about 25% of the time when running this test (requires Cassandra): https://github.com/thobbs/phpcassa/blob/master/test/test_large_ops.php The patched version of this does run quite a bit faster, so that's a nice bonus. Thanks for the hard work, Nicholas! Hopefully we can get to the bottom of this.
          Hide
          Bryan Duxbury added a comment -

          You can use the ThriftTest server from another language, like java.

          Show
          Bryan Duxbury added a comment - You can use the ThriftTest server from another language, like java.
          Hide
          Nicholas Telford added a comment -

          My major concern is that I can't find an effective way to run the existing test suite (for PHP at least). Specifically, in order to run the ThriftTest client tests, I need to run a ThriftTest server,

          For what it's worth, I've managed to test this patch with both TBufferedTransport and TFramedTransport (with the patch in THRIFT-867) with my own set of homebrew scripts. I'm pretty confident about it, but I'd feel better with a complete test suite. That's something I may work on tomorrow if I get the chance.

          Show
          Nicholas Telford added a comment - My major concern is that I can't find an effective way to run the existing test suite (for PHP at least). Specifically, in order to run the ThriftTest client tests, I need to run a ThriftTest server, For what it's worth, I've managed to test this patch with both TBufferedTransport and TFramedTransport (with the patch in THRIFT-867 ) with my own set of homebrew scripts. I'm pretty confident about it, but I'd feel better with a complete test suite. That's something I may work on tomorrow if I get the chance.
          Hide
          Bryan Duxbury added a comment -

          I have yet to figure out an effective way to test changes.

          How about you make a server implementation that intentionally waits longer than the clientside timeout?

          Show
          Bryan Duxbury added a comment - I have yet to figure out an effective way to test changes. How about you make a server implementation that intentionally waits longer than the clientside timeout?
          Hide
          Nicholas Telford added a comment -

          Some digging revealed that stream_socket_recv() and stream_socket_sendto() do not respect timeouts, as Chris mentioned earlier. From http://php.net/stream_set_timeout:

          This function doesn't work with advanced operations like stream_socket_recvfrom(), use stream_select() with timeout parameter instead.

          The attached patch is a fairly major refactoring of TSocket to use stream_select() for timeout detection. From what I can tell it works fine, although there may be issues with TFramedTransport. I have yet to figure out an effective way to test changes.

          It should also be a little more robust for writing large chunks of data as write() will now block until all the data has been sent.

          Would seriously appreciate any testing people contribute.

          Show
          Nicholas Telford added a comment - Some digging revealed that stream_socket_recv() and stream_socket_sendto() do not respect timeouts, as Chris mentioned earlier. From http://php.net/stream_set_timeout: This function doesn't work with advanced operations like stream_socket_recvfrom(), use stream_select() with timeout parameter instead. The attached patch is a fairly major refactoring of TSocket to use stream_select() for timeout detection. From what I can tell it works fine, although there may be issues with TFramedTransport. I have yet to figure out an effective way to test changes. It should also be a little more robust for writing large chunks of data as write() will now block until all the data has been sent. Would seriously appreciate any testing people contribute.
          Hide
          Nicholas Telford added a comment -

          Another quick note: because readAll() loops until all the data has been read and socket timeouts are the idle time for a socket, the loop will execute for at most ($len * $recvTimeout) seconds.

          If we want a timeout for the entire data chunk (i.e. for execution of the entire readAll() call) we will need to add some manual timing to readAll(). This doesn't just apply to TSocket, but any TTransport that has the same while (...)

          { $this->read(); }

          behaviour.

          Show
          Nicholas Telford added a comment - Another quick note: because readAll() loops until all the data has been read and socket timeouts are the idle time for a socket, the loop will execute for at most ($len * $recvTimeout) seconds. If we want a timeout for the entire data chunk (i.e. for execution of the entire readAll() call) we will need to add some manual timing to readAll(). This doesn't just apply to TSocket, but any TTransport that has the same while (...) { $this->read(); } behaviour.
          Hide
          Nicholas Telford added a comment -

          Take two of the patch:

          • Fixes typo on a variable name (thanks Tyler!)
          • readAll($len) now blocks until the requested bytes have all been read. I've inferred this behaviour from the code that calls it, so if I'm mistaken, let me know.
          • Improved comments on TSocket::read() and TSocket::readAll() to be more explicit about the blocking behaviour of each.

          At first glance, it may seem as though readAll() will tie up CPU in an infinite loop if there's no data available to read on the socket (since stream_socket_recv() is "unbuffered") - however, the underlying recv() syscall blocks until some data arrives on the socket, making this not a problem.

          I've tested this best I can against the PHP test suite, but the test suite seems to be a bit of a mystery, so if anyone has any pointers on using it I'd love to hear it.

          Show
          Nicholas Telford added a comment - Take two of the patch: Fixes typo on a variable name (thanks Tyler!) readAll($len) now blocks until the requested bytes have all been read. I've inferred this behaviour from the code that calls it, so if I'm mistaken, let me know. Improved comments on TSocket::read() and TSocket::readAll() to be more explicit about the blocking behaviour of each. At first glance, it may seem as though readAll() will tie up CPU in an infinite loop if there's no data available to read on the socket (since stream_socket_recv() is "unbuffered") - however, the underlying recv() syscall blocks until some data arrives on the socket, making this not a problem. I've tested this best I can against the PHP test suite, but the test suite seems to be a bit of a mystery, so if anyone has any pointers on using it I'd love to hear it.
          Hide
          Nicholas Telford added a comment -

          You're right, my bad - there was some churn while I was writing the patch, forgot to change the variable names. s/$got/$res/g

          If it's still not stable we should continue to work on it until it is. I was unable to test it against the thrift PHP test-suite for various reasons, but I will try to get a complete set of tests working tomorrow.

          This is of primary concern to me at the moment so I'm going to spend some time re-producing the issues Tyler has identified and work on a solution that's stable for everyone. I'll re-roll the patch once I have something I think will be acceptable.

          Show
          Nicholas Telford added a comment - You're right, my bad - there was some churn while I was writing the patch, forgot to change the variable names. s/$got/$res/g If it's still not stable we should continue to work on it until it is. I was unable to test it against the thrift PHP test-suite for various reasons, but I will try to get a complete set of tests working tomorrow. This is of primary concern to me at the moment so I'm going to spend some time re-producing the issues Tyler has identified and work on a solution that's stable for everyone. I'll re-roll the patch once I have something I think will be acceptable.
          Hide
          Tyler Hobbs added a comment -

          I think the patch has a typo where $got is used instead of $res in write().

          With only that change to the patch, I'm seeing problems when using TFramedTransport with the C extension. With Arya's patch applied from THRIFT-867, I get indefinite hanging. Without it, I get 'TSocket: Could not read 4 bytes'. I'll try to dig in a little further, but I think the patch is still problematic.

          (It's entirely possible that using $res where $got is used is what breaks this.)

          Show
          Tyler Hobbs added a comment - I think the patch has a typo where $got is used instead of $res in write(). With only that change to the patch, I'm seeing problems when using TFramedTransport with the C extension. With Arya's patch applied from THRIFT-867 , I get indefinite hanging. Without it, I get 'TSocket: Could not read 4 bytes'. I'll try to dig in a little further, but I think the patch is still problematic. (It's entirely possible that using $res where $got is used is what breaks this.)
          Hide
          Bryan Duxbury added a comment -

          It certainly sounds like you've got a handle on the issue. I'm willing to commit this patch, if no one else has objections.

          Show
          Bryan Duxbury added a comment - It certainly sounds like you've got a handle on the issue. I'm willing to commit this patch, if no one else has objections.
          Hide
          Nicholas Telford added a comment -

          Patch with the following changes to PHP's TSocket:

          • All reads now done with the unbuffered stream_socket_recv()
          • All writes now done with the unbuffered stream_socket_sendto()
          • Reverted patch to THRIFT-347 that broken reporting of timeouts.
          • Changes TSocket::flush() to be a no-op as PHP is no longer buffering data.
          Show
          Nicholas Telford added a comment - Patch with the following changes to PHP's TSocket: All reads now done with the unbuffered stream_socket_recv() All writes now done with the unbuffered stream_socket_sendto() Reverted patch to THRIFT-347 that broken reporting of timeouts. Changes TSocket::flush() to be a no-op as PHP is no longer buffering data.
          Hide
          Nicholas Telford added a comment -

          This problem is linked to the timeout issues discussed in THRIFT-347, and in fact has been exacerbated by the "fixes" applied for those tickets.

          Specifically, THRIFT-347 was addressed by detecting timeouts with the following expression:

          if (true === $md['timed_out'] && false === $md['blocked'])
          

          The issue here is that $md['blocked'] denotes whether a stream is a blocking (true) or non-blocking (false) stream; since all TSocket streams are blocking (they never change the default, nor should they) this always evaluates to false: The result is, TException is never thrown even for legitimate timeouts.

          This doesn't cause the problem itself, but it handily hides it away by making read() block excessively when there's not enough data to fill the fread() buffer instead of erroneously throwing a TException as it did before. It's also the reason the stream_socket family of functions are reportedly ignoring timeouts. They don't, TSocket is.

          Chris correctly points out that this issue is resolved by replacing fread() calls with stream_socket_recv() calls, however, it's not a bug in PHP (the bug report linked is invalid). fread() is buffered by design - from the php.net docs:

          Reading stops as soon as one of the following conditions is met: length bytes have been read, EOF (end of file) is reached or a packet becomes available or the socket timeout occurs (for network streams)

          My understanding of TSocket is that it's meant as a raw socket abstraction and that any desired buffering should be done in a wrapping TTransport (e.g. TBufferedTransport or TFramedTransport), if that's the case then we should use stream_socket_recv() for all socket reading and stream_socket_sendto() for all socket writing.

          Show
          Nicholas Telford added a comment - This problem is linked to the timeout issues discussed in THRIFT-347 , and in fact has been exacerbated by the "fixes" applied for those tickets. Specifically, THRIFT-347 was addressed by detecting timeouts with the following expression: if ( true === $md['timed_out'] && false === $md['blocked']) The issue here is that $md ['blocked'] denotes whether a stream is a blocking (true) or non-blocking (false) stream; since all TSocket streams are blocking (they never change the default, nor should they) this always evaluates to false: The result is, TException is never thrown even for legitimate timeouts . This doesn't cause the problem itself, but it handily hides it away by making read() block excessively when there's not enough data to fill the fread() buffer instead of erroneously throwing a TException as it did before. It's also the reason the stream_socket family of functions are reportedly ignoring timeouts. They don't, TSocket is. Chris correctly points out that this issue is resolved by replacing fread() calls with stream_socket_recv() calls, however, it's not a bug in PHP (the bug report linked is invalid). fread() is buffered by design - from the php.net docs: Reading stops as soon as one of the following conditions is met: length bytes have been read, EOF (end of file) is reached or a packet becomes available or the socket timeout occurs (for network streams) My understanding of TSocket is that it's meant as a raw socket abstraction and that any desired buffering should be done in a wrapping TTransport (e.g. TBufferedTransport or TFramedTransport), if that's the case then we should use stream_socket_recv() for all socket reading and stream_socket_sendto() for all socket writing.
          Hide
          Jonathan Ellis added a comment -

          This appears to only affect unframed transport, fwiw.

          Show
          Jonathan Ellis added a comment - This appears to only affect unframed transport, fwiw.
          Hide
          ryan rawson added a comment -

          At SU we found that if the TBufferedStream block size != 8192 (hard coded in C) we see the timeout read thing.

          Glad to know we are not alone. I haven't looked at it enough to figure it out yet. Looks like Chris is on to something here?

          Show
          ryan rawson added a comment - At SU we found that if the TBufferedStream block size != 8192 (hard coded in C) we see the timeout read thing. Glad to know we are not alone. I haven't looked at it enough to figure it out yet. Looks like Chris is on to something here?
          Hide
          Chris Goffinet added a comment -

          Reasonable yes, I can test it this weekend. Hopefully it can make the next release.

          Show
          Chris Goffinet added a comment - Reasonable yes, I can test it this weekend. Hopefully it can make the next release.
          Hide
          Bryan Duxbury added a comment -

          Not going to make this release.

          Show
          Bryan Duxbury added a comment - Not going to make this release.
          Hide
          David Reiss added a comment -

          Hey Chris. Does this version of the patch seem reasonable to you?

          Show
          David Reiss added a comment - Hey Chris. Does this version of the patch seem reasonable to you?
          Hide
          Arya Goudarzi added a comment - - edited

          At Gaia, we discovered this happens only when the streams don't contain exact multiples of buffer size, thus there could be cases where the length passed to read() would be larger than the actual data remained to be read from the stream. fread() would block till timeout when the length passed is larger than the actual bytes_left in the stream. So, we are submitting this patch for review. I've tested this to work with our interface.

          Show
          Arya Goudarzi added a comment - - edited At Gaia, we discovered this happens only when the streams don't contain exact multiples of buffer size, thus there could be cases where the length passed to read() would be larger than the actual data remained to be read from the stream. fread() would block till timeout when the length passed is larger than the actual bytes_left in the stream. So, we are submitting this patch for review. I've tested this to work with our interface.
          Hide
          David Reiss added a comment -

          Chris and some people at Facebook have independently discovered that this version does not respect timeouts, which is obviously not acceptable. We're discussing possible solutions.

          Show
          David Reiss added a comment - Chris and some people at Facebook have independently discovered that this version does not respect timeouts, which is obviously not acceptable. We're discussing possible solutions.
          Hide
          Chris Goffinet added a comment -

          stream_socket_recvfrom does not respect timeouts from stream_set_timeout. Investigating more.

          Show
          Chris Goffinet added a comment - stream_socket_recvfrom does not respect timeouts from stream_set_timeout. Investigating more.

            People

            • Assignee:
              Nicholas Telford
              Reporter:
              Chris Goffinet
            • Votes:
              2 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development