We've been having some latency problems with RabbitMQ that seem kinda out of the ordinary given what I've read on this list and in the documentation about it's capabilities. In some cases, the message rate for multiple exchanges simultaneously drops for up to a minute. This is followed by a giant spike as the messages finally rush through. Although no messages appear to be lost, the latency is a problem for us, and any help would be much appreciated.<div>
<br></div><div>== About the environment ==</div><div><br></div><div>- RabbitMQ 2.5.1 (Compiled from source tarball), web admin plugin installed, otherwise out of the box configuration</div><div>- erlang-otp R14B03</div><div>
- Redhat Enterprise 6.0</div>
<div>- IBM 3550, 12 cores, 192G memory (no, that's not a typo)</div><div>- A single instance of RabbitMQ, receiving roughly 1200 messages per second across 70 (or so) fanout exchanges. Each exchange has 2 queues with one associated consumer per queue. The queues are non-persistant and non-ack. </div>
<div>- There is one publisher per exchange, a Ruby process using the AMQP gem. The consumers also use ruby with the AMQP gem (one is JRuby, the other MRI).</div>
<div><br></div><div>== What we're seeing ==</div><div><br></div><div>I've been able to capture a lot of stats during once of these events, and I've attached some of the resulting data from one that lasted about 12 seconds. What happens (in roughly temporal order) is this:</div>
<div><br></div><div>1) As reported by top, one of the RabbitMQ threads (shown individually in top using the 'H' option) spikes to 100% CPU. By comparing the last used CPU in top to the per-cpu user/system/wait breakdown, it appears the thread is spending all it's time in system calls (see attached screenshot).</div>
<div><div>2) As reported by netstat, TCP receive queues build up on the incoming RabbitMQ socket connections. This happens in just a few seconds. See the attached netstat.txt file for detailed stats from a particular episode.</div>
<div>3) The web admin plugin stops responding to API requests.</div></div><div>4) The incoming message rate across multiple exchanges drops dramatically. The system can stay in this state for 10-30 seconds or more.</div><div>
5) The CPU levels return to normal (sometimes a bit above normal), and the message rate jumps. Some queuing on the consumers happens as they try to catch up with flood of messages.</div><div>6) The consumers work off the extra messages, and the system returns to normal (40%, or so, cpu for rabbit, < 5% for the consumers).</div>
<div><br></div><div>These episodes last from just a couple of seconds up to a minute, and seem to happen randomly, sometimes coming one right after another, sometimes hours apart. We've never seen it less than once a day.</div>
<div><br></div><div>==What we've already done==</div><div><br></div><div>1) Troubleshooting using strace</div><div>Since the thread seems to be pegged in system calls, we've been using strace to try and capture the system call made by the offending thread during the event. Unfortunately, the best we've been able to do is capture the system calls immediately following the event. For example, here are the first system calls captured for two threads, once of which can be seen with a pegged CPU in the attached screenshot (pid 21860).</div>
<div><br></div><div><div>$ head rabbit-thread.21860</div><div>21:13:53.109706 futex(0x1f2bc20, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000021></div><div>21:13:53.109805 futex(0x1f2bb60, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000018></div>
<div>21:13:53.109853 futex(0x899240, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 <0.006322></div></div><div><br></div><div><div><div>$ head rabbit-thread.21862 </div><div>21:13:48.663530 futex(0x1f2bce0, FUTEX_WAIT_PRIVATE, 4294967295, NULL) = 0 <4.446544></div>
<div>21:13:53.110118 sched_yield() = 0 <0.000102></div><div>21:13:53.110334 futex(0x1f856e8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 <0.006364></div><div>21:13:53.116735 futex(0x1f856e8, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000092></div>
<div>21:13:53.117139 recvfrom(204, "</div></div></div><div><br></div><div>The first system call logged for 21860 occurs at 21:13:53. However, notice the timestamp and 4.4 second execution time for the futex call in the other thread (21862). All of the straces for the threads were started at the same time (using the -ff option) and a number of other threads have a similar call around 21:13:48.6635 as their first logged system call (within a few milliseconds). This leads me to believe that whatever 21860 is doing during this time, it's working in a single system call rather than repeatedly calling in a loop. </div>
<div><br></div><div>2) Reproducing the problem in a controlled environment</div><div><br></div><div>This problem only seems to occur in our production environments, but not in any test environments. The software and hardware in the two environments are identical. We've used data recorded from our prod environment to try and reproduce the problem in test (with higher load, even), but no luck so far.</div>
<div><br></div><div>3) Monitoring message rates through the web API</div><div><br></div><div>In the second attached screenshot, you can see a graph generated from data pulled from the web API for this episode. Each trace in the graph represents the incoming message rate for an individual exchange as reported by the API. For example, the green line at the top shows the message rate dropping from 223 messages/sec to 32 messages per second. Not all the exchanges</div>
<div><br></div><div>Note that the sample rate for this query is every 5 seconds, and the straight line between the points at 21:13:40 and 21:13:53 indicate that the script pulling the data was unable to get a response from rabbit during this time.</div>
<div><br></div><div>4) Restarting Rabbit</div><div><br></div><div>It's not clear that restarting rabbit has any effect on this problem. Because it's so random, it's hard to tell if a rabbit restart makes things better. </div>
<div><br></div><div><br></div><div>I've got more data on this if anyone wants to hear it. Thanks in advance for your help.</div><div><br></div><div>Ben</div>