!!Urgent!! - Sending Messages not possible due to ActiveMQ in Blocked state

[surajsathyapal]

We are currently using ActiveMQ 5.3.1 in our application with a shared file system master/slave approach on NFS. In the current scenario we are running the ActiveMQ process on a Linux box with non-root user account. We have configured the producer/consumer using Spring JMS and have a custom Authentication plugin and no problems with the connection.

Recently we started experiencing an issue wherein the sending of messages from producer application gets into block state ( We are not using Producer Control flow ? Pls refer to ActiveMQ.xml configuration attached along) . On Debugging the issue further we saw in the ActiveMq thread dump, that the sender queue is blocked (thread dump attached along). It has also been noticed that this seems to happen when there is no activity on the AMQ for a few hours.

We are blocked due to this behavior ? the workaround is to restart ActiveMQ.  Tried turning on  level but it doesn?t give much details. Appreciate any other stuff we need to look into or any pointer.

-

---

Thread Dump----

---

INFO   | jvm 1    | 2011/03/15 02:27:52 | "ActiveMQ NIO Worker" daemon prio=10 tid=0x00002aab784a3800 nid=0x2a48 waiting for monitor entry INFO   | jvm 1    | 2011/03/15 02:27:52 |    java.lang.Thread.State: BLOCKED (on object monitor)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:558)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       - waiting to lock <0x00002aaab3d81840> (a java.lang.Object)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.Queue.send(Queue.java:539)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:354)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:445)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:95)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:224)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:126)INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:133)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:453)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:631)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:303)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:181)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:216)
INFO | jvm 1 | 2011/03/15 02:27:52 | - locked <0x00002aaab560e730> (a org.apache.activemq.transport.InactivityMonitor$1)INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.NIOTransport.serviceRead(NIOTransport.java:128)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.NIOTransport.access$000(NIOTransport.java:44)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.NIOTransport$1.onSelect(NIOTransport.java:68)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.SelectorSelection.onSelect(SelectorSelection.java:94)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.SelectorWorker$1.run(SelectorWorker.java:119)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at java.lang.Thread.run(Unknown Source)

INFO   | jvm 1    | 2011/03/15 02:27:52 |

INFO   | jvm 1    | 2011/03/15 02:27:52 | "ActiveMQ NIO Worker" daemon prio=10 tid=0x00002aab78108800 nid=0x2867 waiting for monitor entry

INFO   | jvm 1    | 2011/03/15 02:27:52 |    java.lang.Thread.State: BLOCKED (on object monitor)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:738)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       - waiting to lock <0x00002aaab3d314a8> (a java.lang.Object)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.store.kahadb.MessageDatabase.access$500(MessageDatabase.java:82)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.store.kahadb.MessageDatabase$11.visit(MessageDatabase.java:695)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.store.kahadb.data.KahaAddMessageCommand.visit(KahaAddMessageCommand.java:205)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:692)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:644)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.addMessage(KahaDBStore.java:145)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:571)
INFO | jvm 1 | 2011/03/15 02:27:52 | - locked <0x00002aaab3d81840> (a java.lang.Object)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.Queue.send(Queue.java:539)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:354)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:445)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:95)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:224)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:126)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:133)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:453)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:631)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:303)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:181)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
INFO | jvm 1 | 2011/03/15 02:27:52 | at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:216)
INFO | jvm 1 | 2011/03/15 02:27:52 | - locked <0x00002aaab46dead8> (a org.apache.activemq.transport.InactivityMonitor$1)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.NIOTransport.serviceRead(NIOTransport.java:128)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.NIOTransport.access$000(NIOTransport.java:44)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.NIOTransport$1.onSelect(NIOTransport.java:68)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.SelectorSelection.onSelect(SelectorSelection.java:94)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at org.apache.activemq.transport.nio.SelectorWorker$1.run(SelectorWorker.java:119)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

INFO   | jvm 1    | 2011/03/15 02:27:52 |       at java.lang.Thread.run(Unknown Source)

[basheeruddin]

We are using NFS share and both AMQs are pointed to the share it happens after SyncFailedException... The log file snippet and the thread dump is here

-

---

INFO   | jvm 1    | 2011/04/04 21:03:36 |       at java.io.FileDescriptor.sync(Native Method)

INFO   | jvm 1    | 2011/04/04 21:03:36 |       at org.apache.kahadb.page.PageFile.writeBatch(PageFile.java:1007)

INFO   | jvm 1    | 2011/04/04 21:03:36 |       at org.apache.kahadb.page.PageFile.pollWrites(PageFile.java:920)

INFO   | jvm 1    | 2011/04/04 21:03:36 |       at org.apache.kahadb.page.PageFile.access$000(PageFile.java:65)

INFO   | jvm 1    | 2011/04/04 21:03:36 |       at org.apache.kahadb.page.PageFile$2.run(PageFile.java:1127)

INFO   | jvm 1    | 2011/04/04 21:03:36 |  WARN | KahaDB PageFile flush: 1 queued writes, latch wait took 201917

INFO   | jvm 1    | 2011/04/04 21:03:36 |  INFO | Slow KahaDB access: cleanup took 201918

-

---

INFO   | jvm 1    | 2011/04/04 22:09:06 | 2011-04-04 22:09:06

INFO   | jvm 1    | 2011/04/04 22:09:06 | Full thread dump Java HotSpot(TM) 64-Bit Server VM (16.0-b13 mixed mode):

INFO   | jvm 1    | 2011/04/04 22:09:06 |

INFO   | jvm 1    | 2011/04/04 22:09:06 | "ActiveMQ NIO Worker" daemon prio=10 tid=0x000000005c7ae800 nid=0x3d14 waiting for monitor entry

INFO   | jvm 1    | 2011/04/04 22:09:06 |    java.lang.Thread.State: BLOCKED (on object monitor)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:558)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       - waiting to lock <0x00002aaab3cae460> (a java.lang.Object)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.region.Queue.send(Queue.java:539)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:354)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:445)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:95)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:224)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:126)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:133)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:453)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:631)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:303)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:181)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
INFO | jvm 1 | 2011/04/04 22:09:06 | at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:216)
INFO | jvm 1 | 2011/04/04 22:09:06 | - locked <0x00002aaab4c2bb10> (a org.apache.activemq.transport.InactivityMonitor$1)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.transport.nio.NIOTransport.serviceRead(NIOTransport.java:128)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.transport.nio.NIOTransport.access$000(NIOTransport.java:44)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.transport.nio.NIOTransport$1.onSelect(NIOTransport.java:68)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.transport.nio.SelectorSelection.onSelect(SelectorSelection.java:94)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at org.apache.activemq.transport.nio.SelectorWorker$1.run(SelectorWorker.java:119)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

INFO   | jvm 1    | 2011/04/04 22:09:06 |       at java.lang.Thread.run(Unknown Source)