100% CPU usage from network activity loop about bunny HOT 42 CLOSED

Can you strace the running process and paste the result?

from bunny.

sure:

just doing a count for 5 seconds:

> strace -c -p 447
Process 447 attached - interrupt to quit
^CProcess 447 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 89.99    0.037997           0     99975     27392 futex
  9.45    0.003989           0     38960           clock_gettime
  0.56    0.000236           0      2750           write
------ ----------- ----------- --------- --------- ----------------
100.00    0.042222                141685     27392 total

and here the raw thing:

> strace  -p 447
futex(0x22a8618, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x22a7f30, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {2238751, 677353882}) = 0
clock_gettime(CLOCK_MONOTONIC, {2238751, 677377007}) = 0
futex(0x22a7f64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x22a7f60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x22a7f30, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x22a85b4, FUTEX_WAIT_BITSET_PRIVATE, 1701450561, {2238751, 972629007}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x22a8618, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {2238751, 677506124}) = 0
clock_gettime(CLOCK_MONOTONIC, {2238751, 677530389}) = 0
futex(0x22a7f64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x22a7f60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x22a7f30, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x22a85b4, FUTEX_WAIT_BITSET_PRIVATE, 1701450563, {2238751, 972629389}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x22a8618, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {2238751, 677660735}) = 0
clock_gettime(CLOCK_MONOTONIC, {2238751, 677683942}) = 0
futex(0x22a7f64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x22a7f60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x22a7f30, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x22a85b4, FUTEX_WAIT_BITSET_PRIVATE, 1701450565, {2238751, 972628942}, ffffffff) = -1 ETIMEDOUT 

from bunny.

Thanks

from bunny.

And what Ruby version do you use?

from bunny.

ruby 1.9.3p362 (2012-12-25 revision 38607) [x86_64-linux]

from bunny.

Hey - I could easily switch to the amqp gem for my workers - they seem to not have this (100% CPU) behavior. I simply wanted to avoid using EM in my rails app. Using it in a worker is no problem.

from bunny.

Any news about this issue? I'm having the same problem in production (Gentoo Base System release 1.12.11.1)

from bunny.

I can reproduce it with one test. No idea about the cause yet.

from bunny.

Can you try with master? I fixed at least the cases that reliably reproduced a similar problem.

from bunny.

0.9.0.pre8 is out, please give it a try.

from bunny.

Think this is the same issue I'm seeing (on jruby/logstash):

https://logstash.jira.com/browse/LOGSTASH-940

If so, it's still there on 0.9.0pre8. Do you want me to try to boil down to a minimal test case?

from bunny.

Yes but first try 0.9.0.pre8.

from bunny.

Sorry, did say - this is still an issue on 0.9.0pre8. I'll see what I can pare it down to. Thanks.

from bunny.

You can disable network connection recovery, then any exception raised on the network loop thread will
raise an exception in the main thread (where the connection was opened). The exception contains a cause (e.cause)
that will help investigating why the loop does not stop.

from bunny.

@rasputnik I'd be happy to assist in developing a stress test that reproduces the issue if you can explain what
the Logstash client that uses Bunny does.

Some specific questions:

• Does it publish using just one thread?
• If not, can any channels possibly be shared between threads?
• In this case, how reliable is the network connection? If there are known failures, what's a good way to simulate them? (we already have test scripts that kill -9 the broker)
• How soon does the issue happen after restart? (how long should I run the test)
• Are there any traces of publisher blocking in the RabbitMQ log? If either the memory or disk space alarm goes off, RabbitMQ will log a warning and stop reading from the socket until the alarm clears.

Just to make it clear, this is the most important issue in Bunny 0.9 I am aware of and I'm happy to offer any help I can to get to the root of it.

from bunny.

my initial snippet still shows the behaviour. No need to do anything, just subscribe to a single queue -> 100% CPU

from bunny.

@thieso2 how long does it take? what if you enable heartbeats?

from bunny.

It start immediately to eat one CPU. Using Bunny.new(:heartbeat_interval => x) (tried x = 1 and x = 100) does not change anything.

BTW: maybe I should mention that I run in a OpenVZ container on Linux.

I could (not today but soon) give you SSH to one box that shows this problem, would that help?

from bunny.

Well, Bunny 0.9 uses a network activity thread that basically does while true. I will look into switching it to use
IO.select in a way that does not involve constant looping.

from bunny.

@thieso2 when you have a chance to share access to the container that reproduces the problem, email me (see my profile page). Thanks.

from bunny.

Here's a snippet that reproduces it. (NB: no issue with default gem 0.8.0).

https://gist.github.com/rasputnik/5160442

It's a chopped down version of the logstash plugin from master.

run with:

jruby --1.9 -S gem install cabin
jruby --1.9 -S gem install bunny -v 0.9.0pre8
jruby -J-Djruby.reify.classes=true --1.9 rabbitout.rb

After 10 minutes a CPU core hits 100%.
Rabbit is 3.0.1. only thing in its logs are:

=INFO REPORT==== 14-Mar-2013::10:35:36 ===
accepting AMQP connection <0.25025.2> (10.224.4.96:54655 -> 10.224.4.152:5672)

=WARNING REPORT==== 14-Mar-2013::10:46:01 ===
closing AMQP connection <0.25025.2> (10.224.4.96:54655 -> 10.224.4.152:5672):
connection_closed_abruptly

(the second 'closing...' line is from ^C ing the JRuby script). tcpdump isn't showing
any traffic over 5672 between client and server after the initial bind to the exchange,
until the 10 minute CPU jump. I just get a short burst of traffic, then it's silent again
but the CPU stays at 100%

1:05:48.682811 IP (tos 0x0, ttl 64, id 5486, offset 0, flags [DF], proto TCP (6), length 60)
mydesktop.54754 > theamqpserver.amqp: Flags [P.], cksum 0x2e6c (correct), seq 473:481, ack 397, win 8210, options [nop,nop,TS val 518385281 ecr 1221511172], length 8
11:05:48.721889 IP (tos 0x0, ttl 64, id 34039, offset 0, flags [DF], proto TCP (6), length 52)
theamqpserver.amqp > mydesktop.54754: Flags [.], cksum 0x35df (correct), seq 397, ack 481, win 243, options [nop,nop,TS val 1222109309 ecr 518385281], length 0
11:05:50.505341 IP (tos 0x0, ttl 64, id 34040, offset 0, flags [DF], proto TCP (6), length 60)
theamqpserver.amqp > mydesktop.54754: Flags [P.], cksum 0x1ee6 (incorrect -> 0x260a), seq 397:405, ack 481, win 243, options [nop,nop,TS val 1222111092 ecr 518385281], length 8
11:05:50.505838 IP (tos 0x0, ttl 64, id 25689, offset 0, flags [DF], proto TCP (6), length 52)
mydesktop.54754 > theamqpserver.amqp: Flags [.], cksum 0x08b1 (correct), seq 481, ack 405, win 8210, options [nop,nop,TS val 518387089 ecr 1222111092], length 0

from bunny.

Just an additional datapoint. Get exactly the same behaviour running rabbitmq 3.0.2 on localhost and connecting to that. If you need any more details or tests get in touch, cheers.

from bunny.

Are you running on bare metal or in an OpenVZ container, too?

from bunny.

Client is a mountain lion mac (but first spotted the issue on a VMware instance).

The remote server is rabbitmq 3.0.1 on centos6 in a xen vm.

vms and xen run logstash 1.1.9 (bunny 0.8.0) fine - same exchange hosted on same xen box, same JVMs, etc.

But see the same issue with rabbitmq 3.0.2 running locally (installed via homebrew).

Just trying that :automatically_recover=>false option, will update you in about 10 minutes :)

• ten minutes later -

no, same behaviour, no exceptions thrown just high CPU.

from bunny.

Having exactly the same issue on rabbitmq 3.0.4 with 0.9.0pre8. Platform is EL 6.4 on x86_64 (vmware) running ruby 1.9.3 and/or logstash 1.1.9 and 1.1.10 (latest master branch). If I can do any further testing, don't hesitate to ask.

from bunny.

@sgzijl posting strace output of the process and trying to reproduce it with the script posted above would help a lot. Thank you.

from bunny.

@michaelklishin my VM is still running and shows the problem....

from bunny.

I might have a solution.
TLDR: set :heartbeat in your bunny options explicitly to zero.

For me the issue was that, after exactly 10 mins of normal operation (under jruby), my process would start using 100% CPU.

With the introduction of AMQP 0.9.1, the default timeout value for heartbeating has changed from 0 ('off') to 600 seconds. Your server's configuration (being either v0.8 or v0.9.1) may still specify heartbeat '0'. The new v0.9 bunny gem, however, will adhere to the standard and default to trying to heartbeat the server with a timeout of 600 seconds.
The trouble is: the heartbeat is leading in establishing if a connection is alive. Messages being happily passed between the two parties have no effect on it's perceived 'aliveness'.

After the heartbeat timeout has run out, bunny throws in the towel and starts to consume all those delicious CPU cycles while wallowing in it's own misery...so to speak.

The solution: configure :heartbeat on server and client. Turn them both either on or off, and you'll be grand.

from bunny.

@blaet any network activity should be considered a heartbeat by the spec. Are you saying that Bunny does not
respect that (it may be the case)? Plus, heartbeats are sent out at about 1/4 the interval specified to avoid some
edge cases.

If you set hearbeat interval to a low value (say, 10 seconds), does it reproduce the issue? May I ask you for a script that does that? Are you running in a virtualized environment as well?

from bunny.

@michaelklishin yep, just tried it. when heartbeating is set to 10 sec, after exactly 10 secs under JRuby 1.7.3 it behaves as described above. Will post a snippet later on.

from bunny.

@michaelklishin we've been seeing this issue under JRuby 1.6.8 and have tried @blaet suggestion. Setting both the RabbitMQ server and the bunny client to have a heartbeat of 0 seems to stop the application from spiking the CPU usage. Setting non-zero values, but equal on both server & client, still exhibit the CPU spike, as do differing explicit values apparently.

from bunny.

@mattdenner @blaet thanks for the clarification. Does RabbitMQ log contain any lines after this happens?

from bunny.

I believe I understand the issue, it is with handling of connections closed by RabbitMQ.

from bunny.

@michaelklishin awesome! thanks for the effort

from bunny.

I reduced examples to the following and on master, it does not reproduce the issue:

require "bundler"

Bundler.setup

require "bunny"

conn = Bunny.new(:port => ENV.fetch("PORT", 5672))
conn.start

puts "Using heartbeat interval #{conn.heartbeat_interval}"

ch   = conn.create_channel
q    = ch.queue("bunny.issue95", :durable => false)
x    = ch.default_exchange

i = 0

loop do
  puts i
  i += 5.0
  sleep 5.0
end

(note that Bunny::Session#heartbeat_interval is new in master).

It would be great if more people could verify it. To not make you think the issue has fixed itself, here are
specific things that were changed:

• TCP keep-alive is now on by default
• Bunny will now use a heartbeat interval offered by RabbitMQ until you configure it explicitly
• Connection failure handler will now kick in after some time (5 seconds by default, can be set via :network_recovery_interval) instead of immediately, no longer stepping over everything else that may have been going on with the connection
• If heartbeat sender hits an I/O error, it simply stops instead of trying to continue (I believe this has caused the tight loop, although not sure why it wasn't shut down upon reconnection). This is fine because when if/when we reconnect, it will be discarded and a new instance will be created anyway.

I will try @thieso2's container later today.

from bunny.

In the container @thieso2 has made available for me to investigate, I see a sequence of the following calls repeated ad infinum:

write(4, "!", 1)                        = 1
futex(0x1d418b0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x1d418e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x1d418e4, FUTEX_WAIT_PRIVATE, 316701, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x1d418b0, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6275433, 400293842}) = 0
clock_gettime(CLOCK_MONOTONIC, {6275433, 400335101}) = 0
futex(0x1d418e4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1d418e0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1d418b0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x1d41f34, FUTEX_WAIT_BITSET_PRIVATE, 3785787, {6275435, 553982101}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1d41f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6275433, 400625085}) = 0
clock_gettime(CLOCK_MONOTONIC, {6275433, 400670036}) = 0
futex(0x1d418e4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1d418e0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1d418b0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x1d41f34, FUTEX_WAIT_BITSET_PRIVATE, 3785789, {6275435, 553985036}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1d41f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6275433, 400934271}) = 0
clock_gettime(CLOCK_MONOTONIC, {6275433, 436512454}) = 0
futex(0x1d418e4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1d418e0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1d418b0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x1d41f34, FUTEX_WAIT_BITSET_PRIVATE, 3785791, {6275435, 589518454}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1d41f98, FUTEX_WAKE_PRIVATE, 1) = 0

Note ETIMEDOUT and EAGAIN, those pop up repeatedly. Googling for key constants in this trace bring up
two issues:

• The leap second bug which happened in July 2012. This is with Ruby 1.9.3, not JRuby.
• This issue with Puppet which boiled down to a misconfiguration of iptable rules.

I'm continuing investigating, hopefully @thieso2 will bump my permissions soon. If anyone has pointers at what ETIMEDOUT and EAGAIN may be indicating, please let me know. RabbitMQ is running on the same host.

from bunny.

The following OpenVZ bug may be relevant, the system is running

$ uname -a
Linux rails 2.6.32-14-pve #1 SMP Tue Aug 21 08:24:37 CEST 2012 x86_64 x86_64 x86_64 GNU/Linux

just like the report suggests.

from bunny.

Switching to :heartbeat => 0 and :threaded => false (so, Bunny ever only uses one Ruby thread), makes strace report this:

futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813091, {6276977, 8606232}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 440843639}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 440886886}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813093, {6276977, 8607886}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441030036}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441071719}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813095, {6276977, 8605719}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441216854}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441260148}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813097, {6276977, 8608148}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441417782}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441463740}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813099, {6276977, 8610740}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441621347}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441663210}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813101, {6276977, 8606210}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441809160}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441852120}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813103, {6276977, 8607120}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 441994826}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 442035881}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813105, {6276977, 8605881}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 442183827}) = 0
clock_gettime(CLOCK_MONOTONIC, {6276975, 442226825}) = 0
futex(0x1b23f34, FUTEX_WAIT_BITSET_PRIVATE, 6813107, {6276977, 8607825}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x1b23f98, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, ^C{6276975, 442370808}) = 0

endlessly, which seems identical to this Passenger issue (another report).

from bunny.

Another very similar report for Redmine, seems to be the leap second bug.

from bunny.

After some back and forth with @thieso2, I think the issue is solved (by rebooting the machine, which reset the clock). CPU consumption is now between 0.0% and 2%, mostly below 0.5.

So, to summarize, there were 2 issues that caused CPU spikes:

• Heartbeat sender could slip into an infinite loop if it had an exception
• Network recovery was too eager to kick in as soon as there was an I/O error

plus a system-specific variation of the leap second bug under OpenVZ. 0.9.0.pre9 solves the first two. The 3rd one
is outside of the scope of this GH issue.

I'm going to release 0.9.0.pre9 later today and closing this issue.

from bunny.

0.9.0.pre9 is released

from bunny.

Thanks for the effort. Much appreciated!

from bunny.