Use a socket timeout instead of Ruby's timeout

[rrosenblum]

Ruby's timeout has some serious issues. Rather than using Ruby's timeout for socket timeouts, it would be better to use setting on the socket itself or IO.select.

I was recently profiling a worker that we have that sends messages out to ActiveMQ. During the profiling, I found that nearly 70% of all the memory being allocated for this worker comes from Ruby's timeout. It is a very simple resque worker that gets a message and writes it to ActiveMQ using stomp. We maintain the same Stomp::Client for all of the messages that we send. I profiled this worker with 1000 messages. The total allocated memory was 1527649456 bytes. The total memory being allocated by timeout was 1052953152 bytes.

Example of using timeout on the socket - https://www.mikeperham.com/2009/03/15/socket-timeouts-in-ruby/
Example using IO.select - https://spin.atomicobject.com/2013/09/30/socket-connection-timeout-ruby/

[gmallard]

Thanks for the report.

We will look into this.

My personal recollection is that IO.select was used at one time (a number of years ago), but was abandoned because:

a) It failed on Windows, or
b) It failed on JRuby, or
c) both a) and b)

Out of curiosity, what profiling tool(s) were used to obtain your results ?

[rrosenblum]

The gem that I used is MemoryProfiler. So far, it has been the best gem that I can find for memory profiling.

That is a shame if IO.select didn't work on Windows or JRuby. It is hopefully still possible to accomplish a timeout using socket options.

[gmallard]

Timeout::timeout ....

is called five places in gem code ( ignoring unit tests ).

For each of:

• Connect timeout (two places, once for TCP and once for SSL)
• Frame parse timeout
• Socket read timeout
• Start timeout (peculiar to ::Client, not used in ::Connection)

Are your results 'localized', or for all calls ?

[rrosenblum]

Unfortunately, the results that I was looking at were generalized to Timeout.timeout. I think this is at least partially due to the fact that Timeout.timeout is written in Ruby so MemoryProfiler is able to count it as a source.

For the code that I was running, I was persisting the client and looping over a set of messages. Most likely, because of how this was running, connect and start timeout would be negligible. The code that would be executed most is frame parse and socket read. I did memory profile a modified version of my code that reconnected for every message that was sent. This caused the allocated memory to triple that of a persisted connection.

I can attempt to rerun a profile excluding Ruby source code. I do not know if this will have the effect of hiding the results from Ruby source or if it will cause all of the results to point one level higher.

As far as I know, there should be socket level settings to handle the timeout of connect and read. I would think there is also a socket setting for frame parse. There is also a socket setting for connect timeout. Looking at the code, I assume that the main reason for the start timeout in Client is because of the create_connection. If we can get a socket level connect timeout to work, then there should be no need for the Ruby timeout anymore.

[gmallard]

I have not forgotten about this.

I spent some time this week end starting to put together a test bed, in order to get some before and after results.

I confused myself for a while because of the similarity of gem names:

• https://github.com/SamSaffron/memory_profiler
• https://github.com/phluid61/memory-profiler-gem

In any case I would like a little more information from you.

• You say you use Stomp::client for 'all the messages you send'. Do you receive messages as well? If so, do the receives happen in the same process ? In short, where does the data to send come from?
• Does your call to Stomp::client#publish supply a 'receipt listener' call back proc ?
• What STOMP protocol level are you using? If you are using 1.1 or 1.2 do you use heartbeats? If you use heartbeats, what are the negotiated values after connect ?
• Which style of connect parameters are you using? Show me an example please.
• Can you show me a brief code sequence of exactly how you are using the memory_profiler gem?
• What version of ActiveMQ is being used?
• How many message per hour/minute/second are sent ? Same question about anoy received messages.
• How large are the messages (approximately) ?

I really think I need to know a little more about the overall design and implementation of your application. Is the application source available to the public?

Your statement that TImeout.timeout was written in Ruby surprised me. I am looking at a ruby 2.3.2p113 system and you are indeed correct. My surprise was because I have looked at Timeout.timeout before, a few years ago. At one point (1.8 or 1.9 maybe) I am pretty confident it was written in C. I wonder why the Ruby developers changed that.

[rrosenblum]

Unfortunately the project that I working on is closed source. I will work on putting together a generic implementation of the code to give to you. To give you some more information on this, the reason that I started looking into this is that we found that our ActiveMQ workers were leaking memory. Running memory_profiler, the retained memory pointed to lib/connection/netio.rb:176 (used_socket.write body unless body == '') being the issue. It seems as though maintaining a long lived socket may cause memory leaks. I also saw a very high amount of allocated memory pointing to Timeout.timeout which prompted me to create this issue.

Without a more detailed example right now, the closest example to our setup is the publisher example. We initialize a connection, then rely on rescue to retrieve messages on a queue that will be sent out.

• You say you use Stomp::client for 'all the messages you send'. Do you receive messages as well? If so, do the receives happen in the same process ? In short, where does the data to send come from?
• Does your call to Stomp::client#publish supply a 'receipt listener' call back proc ?

We publish a message and wait for a receipt. The only messages received by this worker are receipts. The implementation is:

receipt = false
client.publish(destination, message, headers) { |r| receipt = r }
Thread.pass until receipt

• What STOMP protocol level are you using? If you are using 1.1 or 1.2 do you use heartbeats? If you use heartbeats, what are the negotiated values after connect ?
• Which style of connect parameters are you using? Show me an example please.

Here is an example of our connection parameters

Stomp::Client.new(:connect_headers=>{"accept-version"=>"1.1", "host"=>"host", "heart-beat"=>"15000,20000"},
 :hosts=>[{:host=>"host", :port=>port, :login=>"login", :passcode=>"passcode"}, {:host=>"host", :port=>port, :login=>"login", :passcode=>"passcode"}],
 :reliable=>true,
 :randomize=>false,
 :closed_check=>true,
 :initial_reconnect_delay=>1,
 :max_reconnect_delay=>30,
 :max_reconnect_attempts=>0,
 :max_hbread_fails=>2,
 :max_hbrlck_fails=>2,
 :fast_hbs_adjust=>0.1,
 :use_exponential_back_off=>false,
 :connect_timeout=>5,
 :start_timeout=>nil,
 :logger=> #<StompLogger>)

• Can you show me a brief code sequence of exactly how you are using the memory_profiler gem?

I had to open up resque and wrap a chunk of their work code in memory_profiler. I will work on getting a better example.

• What version of ActiveMQ is being used?

5.13.3

• How many message per hour/minute/second are sent ? Same question about anoy received messages.

Average number of messages sent in a week is 3.4 million. Which comes to about 20,000 per hour, 337 per minute, and 5.6 per second. During busy times we can peak closer to 40,000 messages per hour.

• How large are the messages (approximately) ?

This may take some digging to get a better number. Without using a networking tool to get the exact size, the contents of one of our messages is about 4K of text. It is a json message with about 196 fields.

I hope that this helps. I will work on putting a generic version of this code to post.

[gmallard]

Very good information, all that will be helpful, I am sure. Thanks much.

You say:

The only messages received by this worker are receipts.

How does the worker get data to send ? If you can supply a little more technical detail I would appreciate that. I am thinking: file? dbus? zmq? .... how?

You also say:

I had to open up resque and wrap a chunk of their work code in memory_profiler. I will work on getting a better example.

And later:

I will work on putting a generic version of this code to post.

A very simple example of the memory_profiler wrapping would be very good. I think I need that.

I also need to think about your use of resque. That might (or might not) change what I need to be thinking about regarding this issue.

And last but not least, thanks for the detailed connect parameters. That alone has given me several items to think about.

Thanks, Guy

[gmallard]

You will get tired of my questions. Is yours a Rails application?

[rrosenblum]

More questions are a good thing. I found out that the average message size is 15993 bytes (15.62K), the minimum message size is 1292 bytes, and the maximum message size is 67782 bytes.

Yes, this is a Rails application. We are running Ruby 2.2.4 with Rails 3.2.22.2 (working on upgrading to 4.2.6) and Resque 1.25.2

How does the worker get data to send ? If you can supply a little more technical detail I would appreciate that. I am thinking: file? dbus? zmq? .... how?

We get the data from Resque and Redis. In our application we will build a message, enqueue it onto a Redis queue and let Resque pick up the work for the worker. We did this to move direct communication with ActiveMQ out of our web app and web services.

I also need to think about your use of resque. That might (or might not) change what I need to be thinking about regarding this issue.

We are experiencing what I believe to be 2 issues.

• The first is the amount of allocated memory that is used. This issue points to Timeout being the biggest culprit of allocated memory. Although I have not tested with a generic example, I believe that this can be reproduced in a simple implementation.
• The second issue is that our worker is leaking memory. I believe that this is being caused by us leaving a socket connection to ActiveMQ open for a long period of time.

I am putting together a couple of examples now. I am hoping to post them soon.

[rrosenblum]

Here is a gist of a generic version of our code. The code will not run exactly as is, but I think it is close enough to see what is going on.

Here is a modified version of the publisher example that uses memory profiler and a similar set up to our code. I think that this would be able to show the same issues.

Let me know if you have any other questions.

[gmallard]

Thanks much. I have not looked at those yet ..... but I will.

[gmallard]

So ...... a brief update.

I set up a test bed for this. And it works at this point.

The good news is that I can recreate the effect that you are seeing, that is the memory profiler reports extremely high numbers for file timeout.rb.

I went a bit overboard and have tested with both memory profiler gems (the underscore one which you are using, and the one with a dash in the name).

I want very much to understand why I am seeing what I see. Each call to Timeout::timeout has a specific purpose in the gem. Consider:

1. One call specifically for the read after a 'CONNECT' . A one time use. Reading a CONNECTED or ERROR frame off the wire.
2. One call covering reading and parsing a frame on the inbound wire. Inbound messages would be one of: MESSAGE, ERROR, RECEIPT. This code frequently called by applications that use SUBSCRIBE.
3. One call covering the actual socket open for normal TCP connection. One time use.
4. One other call covering the actual socket opens for an SSL environment. One time use.
5. One call specifically covering the connect sequence in Client#initialize. One time use.

There are a couple of other calls in the unit tests, under the test directory. I am ignoring those.

I know these are the only calls because of:

$ pwd
..../stompgem
$ find . -name '*.rb' -exec grep -Hi "Timeout::timeout" {} \;
./test/test_client.rb:    Timeout::timeout(4) do
./test/test_client.rb:    Timeout::timeout(4) do
./test/test_client.rb:    Timeout::timeout(4) do
./test/test_client.rb:    Timeout::timeout(4) do
./test/test_client.rb:        Timeout::timeout(4) do
./lib/stomp/client.rb:        Timeout::timeout(@start_timeout) {
./lib/connection/netio.rb:            Timeout::timeout(@connread_timeout, Stomp::Error::ConnectReadTimeout) do
./lib/connection/netio.rb:        Timeout::timeout(@parse_timeout, Stomp::Error::PacketParsingTimeout) do
./lib/connection/netio.rb:      Timeout::timeout(@connect_timeout, Stomp::Error::SocketOpenTimeout) do
./lib/connection/netio.rb:        Timeout::timeout(@connect_timeout, Stomp::Error::SocketOpenTimeout) do

This leads me to think that the extreme timeout memory use must be triggered by ..... the 'receipt listener' logic is a guess at this point. I want to investigate some more, and report again later.

[gmallard]

Just to note that the memory balloon is confirmed.

I can recreate using a Client#publish, and supplying a receipt listener. If no receipt listener is used Timeout memory is much smaller.

I wanted to rule out the threading logic in Client. And I did that using Connection#publish. If the #publish headers ask for a receipt, and an immediate call to Connection#receive is used to retrieve the RECEIPT frame, memory use increases considerably. Timeout is at the top again.

At this point I will consider exactly what would need to change to eliminate the memory explosion.

I want to consider whether there are alternatives to the idea behind socket timeouts.

[rrosenblum]

I am glad that you were able to reproduce the bloated memory issue, and that it wasn't just something weird in our setup. I would be glad to help code some solutions to this. My only reservation is that I don't feel as though I know the ActiveMQ protocol well enough to know that a change that I make won't have some other side effect.

I went a bit overboard and have tested with both memory profiler gems (the underscore one which you are using, and the one with a dash in the name).

Always good to have a second opinion.

This leads me to think that the extreme timeout memory use must be triggered by ..... the 'receipt listener' logic is a guess at this point.

I agree with this. It seems to be the only recurring call to timeout. Modifying the others would be nice, but it won't have the same impact on memory since they are only called once.

I want to consider whether there are alternatives to the idea behind socket timeouts.

What are your reservations to using socket timeouts? Are there any other ideas that you have had? I was thinking that socket timeouts were the way to go to fix this since it is implemented in a lower level protocol. There should be settings for different operations allowing separate values for connect, read, write, and anything else that might be needed.

One call covering reading and parsing a frame on the inbound wire. Inbound messages would be one of: MESSAGE, ERROR, RECEIPT. This code frequently called by applications that use SUBSCRIBE.

Looking at the code, these all appear to use the same timeout value which may help complexity of a change.