[AMQ-2389] ActiveMQ hangs on SocketWrite0() with fast producer / slow consumer after MemoryLimit is reached

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: 5.2.0
• Fix Version/s: 5.3.0

Environment

$ cat /proc/version
Linux version 2.6.18-6-amd64 (Debian 2.6.18.dfsg.1-23etch1) ([e-mail]) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #1 SMP Fri Dec 12 05:49:32 UTC 2008

OS X

• Assignee: Robert Davies
• Reporter: Chad Showalter
• Created: 11/Sep/09 19:47
• Updated: 15/Sep/09 17:13
• Resolved: 14/Sep/09 13:59

Description

When persistent=true for the broker, a fast producer / slow consumer may cause ActiveMQ to block on a SocketWrite0() call. The following thread dump signature results:

...
"ActiveMQ Transport: tcp://localhost/127.0.0.1:61610" prio=5 tid=0x0000000101942000 nid=0x1548c4000 waiting for monitor entry [0x00000001548c3000..0x00000001548c3a50]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.activemq.transport.InactivityMonitor.oneway(InactivityMonitor.java:220)

• waiting to lock <0x0000000107d29848> (a java.util.concurrent.atomic.AtomicBoolean)
  at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:185)
  at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
  at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
  at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:185)
  at java.lang.Thread.run(Thread.java:637)
  ...
  "main" prio=5 tid=0x0000000101805000 nid=0x101201000 runnable [0x0000000101200000..0x0000000101200ba0]
  java.lang.Thread.State: RUNNABLE
  at java.net.SocketOutputStream.socketWrite0(Native Method)
  at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
  at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
  at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
  at java.io.DataOutputStream.flush(DataOutputStream.java:106)
  at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:167)
  at org.apache.activemq.transport.InactivityMonitor.oneway(InactivityMonitor.java:233)
• locked <0x0000000107d29848> (a java.util.concurrent.atomic.AtomicBoolean)
  at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:83)
  at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:100)
  at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:40)
• locked <0x0000000107d299b0> (a java.lang.Object)
  at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
  at org.apache.activemq.ActiveMQConnection.doAsyncSendPacket(ActiveMQConnection.java:1214)
  at org.apache.activemq.ActiveMQConnection.asyncSendPacket(ActiveMQConnection.java:1208)
  at org.apache.activemq.ActiveMQSession.send(ActiveMQSession.java:1643)
• locked <0x0000000107d35a68> (a java.lang.Object)
  at org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:227)
  at org.apache.activemq.ActiveMQMessageProducerSupport.send(ActiveMQMessageProducerSupport.java:300)
  at com.chad.test.ActiveMQSpamTest1.runTest(ActiveMQSpamTest1.java:73)
• locked <0x0000000107ca6680> (a org.apache.activemq.ActiveMQMessageProducer)
  at com.chad.test.ActiveMQSpamTest1.main(ActiveMQSpamTest1.java:117)

The attached test instantiates an embedded broker and consistently duplicates the problem on my machine (Macbook Pro running Leopard). The test duplicates behavior we see in production code, which is running an embedded broker on Debian Linux.

I run the test in Eclipse with -Xmx1100mb. The output I see (after a minute or so) is:

...
SENT a (mod 10000) message: i=0
SENT a (mod 10000) message: i=10000
SENT a (mod 10000) message: i=20000
SENT a (mod 10000) message: i=30000
SENT a (mod 10000) message: i=40000
SENT a (mod 10000) message: i=50000
Sep 11, 2009 3:28:13 PM org.apache.activemq.kaha.impl.KahaStore initialize
INFO: Kaha Store using data directory activemq-data/localhost/tmp_storage
RECEIVED a (mod 10000) message: i=10000
RECEIVED a (mod 10000) message: i=20000
RECEIVED a (mod 10000) message: i=30000
RECEIVED a (mod 10000) message: i=40000
RECEIVED a (mod 10000) message: i=50000

after which no further messages are processed, and a thread dump includes the signature shown above. Uncommenting the line

broker.setPersistent(false);

results in the test running to completion (all messages are sent/consumed), with the following output:

SENT a (mod 10000) message: i=0
SENT a (mod 10000) message: i=10000
SENT a (mod 10000) message: i=20000
SENT a (mod 10000) message: i=30000
SENT a (mod 10000) message: i=40000
SENT a (mod 10000) message: i=50000
SENT a (mod 10000) message: i=60000
RECEIVED a (mod 10000) message: i=10000
DONE sending messages
RECEIVED a (mod 10000) message: i=20000
RECEIVED a (mod 10000) message: i=30000
RECEIVED a (mod 10000) message: i=40000
RECEIVED a (mod 10000) message: i=50000
RECEIVED a (mod 10000) message: i=60000