Uploaded image for project: 'ActiveMQ Classic'
  1. ActiveMQ Classic
  2. AMQ-3293

ActiveMQ broker hangs after sending many large messages with a TTL, and no DLQ

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Critical
    • Resolution: Fixed
    • 5.4.2
    • 5.6.0
    • Broker
    • None

    Description

      While doing some ActiveMQ configuration testing I've run into some interesting where I can consistently make ActiveMQ 5.4.2 hang, unable even to shutdown. In this particular case, I have a producer that repeatedly sends persistent TextMessages containing random contents, of a random length up to 4MB to a single queue, with a 30 second TTL. You'll see in the configuration fragments below that we have sendFailIfNoSpace=true and are using vmQueueCursor with a DLQ policy of processExpired=false.

      At some point, the client will get a ResourceAllocationException, as expected once we hit the store limits. I'm running this client in a loop where it will keep trying, and as messages get expired, it will eventually start sending messages again. This will run for awhile, but then the producer will eventually hang. If I kill and restart the producer, it will continue to hang. The jetty console may show a couple of pending messages in the queue, but any consumer also hangs.

      Attempting to shut down activemq results in an error message that a particular connection "is taking a long time to shutdown", however there are no connections to the indicated port (as that producer was killed).

      You can see full thread dumps, lsof output, etc below.

      In another testcase, I was not using vmQueueCursor but this results in OutOfMemory exceptions repeatedly in ActiveMQ, and attempts to restart ActiveMQ hang right after kahadb journal recovery. I do not have a stacktrace or more info from this particular testcase.

      I can sanitize the producer client testcase if needed and attach it.

      ----------

      Full thread dump Java HotSpot(TM) Server VM (1.5.0_22-b03 mixed mode):

      "Simple Discovery Agent: java.util.concurrent.ThreadPoolExecutor$Worker@520fa4" daemon prio=1 tid=0x0a079150 nid=0x16c6 in Object.wait() [0x88d73000..0x88d74100]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90bc0818> (a java.lang.Object)
        at org.apache.activemq.transport.discovery.simple.SimpleDiscoveryAgent$1.run(SimpleDiscoveryAgent.java:136)
      • locked <0x90bc0818> (a java.lang.Object)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:651)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:676)
        at java.lang.Thread.run(Thread.java:595)

      "NetworkBridge" daemon prio=1 tid=0x0a0819d8 nid=0x16c5 waiting on condition [0x883e0000..0x883e0d80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireNanos(AbstractQueuedSynchronizer.java:807)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireNanos(AbstractQueuedSynchronizer.java:1122)
      at java.util.concurrent.SynchronousQueue$Node.waitForPut(SynchronousQueue.java:291)
      at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:443)
      at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:475)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Task" daemon prio=1 tid=0x0a337a10 nid=0x16be waiting on condition [0x87cfc000..0x87cfd100]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:746)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1076)
      at java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync.wlock(ReentrantReadWriteLock.java:342)
      at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:637)
      at org.apache.activemq.broker.TransportConnection$3.run(TransportConnection.java:939)
      at java.lang.Thread.run(Thread.java:595)

      "Simple Discovery Agent: java.util.concurrent.ThreadPoolExecutor$Worker@1ab90e2" daemon prio=1 tid=0x0a875038 nid=0x1621 in Object.wait() [0x891fc000..0x891fcf80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90bc0818> (a java.lang.Object)
        at org.apache.activemq.transport.discovery.simple.SimpleDiscoveryAgent$1.run(SimpleDiscoveryAgent.java:136)
      • locked <0x90bc0818> (a java.lang.Object)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:651)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:676)
        at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Task" daemon prio=1 tid=0x09ba8158 nid=0x15ee waiting on condition [0x88059000..0x88059f80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:746)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1076)
      at java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync.wlock(ReentrantReadWriteLock.java:342)
      at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:637)
      at org.apache.activemq.broker.TransportConnection$3.run(TransportConnection.java:939)
      at java.lang.Thread.run(Thread.java:595)

      "Simple Discovery Agent: java.util.concurrent.ThreadPoolExecutor$Worker@12b6836" daemon prio=1 tid=0x09c814a8 nid=0x15e0 waiting on condition [0x87c7b000..0x87c7bd80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireNanos(AbstractQueuedSynchronizer.java:807)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireNanos(AbstractQueuedSynchronizer.java:1122)
      at java.util.concurrent.SynchronousQueue$Node.waitForPut(SynchronousQueue.java:291)
      at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:443)
      at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:475)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)

      "ConcurrentQueueStoreAndDispatch" daemon prio=1 tid=0x09ef2628 nid=0x157f waiting on condition [0x88ff8000..0x88ff8e00]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1841)
      at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
      at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:470)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Transport: tcp:///10.4.64.66:34904" daemon prio=1 tid=0x09ba7ee8 nid=0x1579 waiting on condition [0x88563000..0x88563e80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:746)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1076)
      at java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync.wlock(ReentrantReadWriteLock.java:342)
      at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:637)
      at org.apache.activemq.broker.region.Queue.sendMessage(Queue.java:1599)
      at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:708)
      at org.apache.activemq.broker.region.Queue.send(Queue.java:644)
      at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:365)
      at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:518)
      at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
      at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
      at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:227)
      at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
      at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
      at org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
      at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
      at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:462)
      at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:677)
      at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:311)
      at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:185)
      at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:69)
      at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
      at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:228)

      • locked <0xa08ab6d8> (a org.apache.activemq.transport.InactivityMonitor$1)
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:220)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:202)
        at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Connection Dispatcher: /10.4.64.66:34904" daemon prio=1 tid=0x0a1a44d8 nid=0x1578 in Object.wait() [0x8b0fe000..0x8b0fef00]
      at java.lang.Object.wait(Native Method)

      • waiting on <0xa08edc38> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0xa08edc38> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "ActiveMQ Connection Dispatcher: vm://cluster_a#6012" daemon prio=1 tid=0x09fca838 nid=0x2c54 in Object.wait() [0x87fd8000..0x87fd9000]
      at java.lang.Object.wait(Native Method)

      • waiting on <0xa07b6438> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0xa07b6438> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "ActiveMQ Connection Dispatcher: vm://cluster_a#3116" daemon prio=1 tid=0x0a7aeb38 nid=0x6139 in Object.wait() [0x87dfe000..0x87dfef80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0xa0791430> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0xa0791430> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "ActiveMQ Transport: tcp:///10.4.64.66:36292" daemon prio=1 tid=0x0a1a4ba0 nid=0x1b15 waiting on condition [0x890fa000..0x890fb080]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:872)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1179)
      at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:201)
      at java.util.concurrent.FutureTask.get(FutureTask.java:80)
      at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:718)
      at org.apache.activemq.broker.region.Queue.send(Queue.java:644)
      at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:365)
      at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:518)
      at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
      at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
      at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:227)
      at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
      at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
      at org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
      at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
      at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:462)
      at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:677)
      at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:311)
      at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:185)
      at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:69)
      at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
      at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:228)

      • locked <0xa0013660> (a org.apache.activemq.transport.InactivityMonitor$1)
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:220)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:202)
        at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Connection Dispatcher: /10.4.64.66:36292" daemon prio=1 tid=0x09caed28 nid=0x1b14 in Object.wait() [0x882de000..0x882df100]
      at java.lang.Object.wait(Native Method)

      • waiting on <0xa00133c8> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0xa00133c8> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Topic ActiveMQ.Advisory.Consumer.Queue.orchestrationResponse" daemon prio=1 tid=0x09e83730 nid=0xbad in Object.wait() [0x87d7d000..0x87d7e000]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x9167a250> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0x9167a250> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Topic ActiveMQ.Advisory.Expired.Queue.orchestrationResponse" daemon prio=1 tid=0x09e846b0 nid=0x17b in Object.wait() [0x884e2000..0x884e2d80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x916643d8> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0x916643d8> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Topic ActiveMQ.Advisory.MessageDLQd.Queue.orchestrationResponse" daemon prio=1 tid=0x0a028150 nid=0x17a in Object.wait() [0x8835f000..0x8835fe00]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x91662a10> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0x91662a10> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Usage Async Task" daemon prio=1 tid=0x0a0c7e30 nid=0x7fdb waiting on condition [0x880da000..0x880dae80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1841)
      at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
      at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:470)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)

      "Topic ActiveMQ.Advisory.Producer.Queue.orchestrationResponse" daemon prio=1 tid=0x0a10d120 nid=0x7fd7 in Object.wait() [0x8815b000..0x8815bf00]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90cc6118> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0x90cc6118> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Topic ActiveMQ.Advisory.Queue" daemon prio=1 tid=0x0a844bb8 nid=0x7fd6 in Object.wait() [0x881dc000..0x881dcf80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90cc2f48> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0x90cc2f48> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Queue:orchestrationResponse" daemon prio=1 tid=0x89680bc8 nid=0x7fd5 waiting on condition [0x8825d000..0x8825e000]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:716)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:872)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1179)
      at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:201)
      at java.util.concurrent.FutureTask.get(FutureTask.java:80)
      at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.removeAsyncMessage(KahaDBStore.java:337)
      at org.apache.activemq.store.kahadb.KahaDBTransactionStore.removeAsyncMessage(KahaDBTransactionStore.java:457)
      at org.apache.activemq.store.kahadb.KahaDBTransactionStore$1.removeAsyncMessage(KahaDBTransactionStore.java:171)
      at org.apache.activemq.broker.region.Queue.acknowledge(Queue.java:797)
      at org.apache.activemq.broker.region.Queue.removeMessage(Queue.java:1527)
      at org.apache.activemq.broker.region.Queue.removeMessage(Queue.java:1519)
      at org.apache.activemq.broker.region.Queue.messageExpired(Queue.java:1584)
      at org.apache.activemq.broker.region.Queue.messageExpired(Queue.java:1574)
      at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1686)
      at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
      at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)

      • locked <0x90cb36c8> (a org.apache.activemq.broker.region.Queue$3)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Topic ActiveMQ.Advisory.Connection" daemon prio=1 tid=0x89783a98 nid=0x7fd4 in Object.wait() [0x88461000..0x88462080]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90cc5188> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:105)
      • locked <0x90cc5188> (a java.lang.Object)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)

      "Timer-1" prio=1 tid=0x898f7bf8 nid=0x7f9c in Object.wait() [0x885e4000..0x885e4e80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90cf75c8> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
      • locked <0x90cf75c8> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

      "HashSessionScavenger-0" daemon prio=1 tid=0x898834c0 nid=0x7f9b in Object.wait() [0x88665000..0x88665f00]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90d4a800> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
      • locked <0x90d4a800> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

      "qtp14633980-49" prio=1 tid=0x895d3050 nid=0x7f9a waiting on condition [0x886e6000..0x886e6f80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-48" prio=1 tid=0x896688c0 nid=0x7f99 waiting on condition [0x88767000..0x88768000]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-47" prio=1 tid=0x896f5660 nid=0x7f98 waiting on condition [0x887e8000..0x887e9080]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-46" prio=1 tid=0x896f4940 nid=0x7f97 waiting on condition [0x88869000..0x8886a100]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-45" prio=1 tid=0x89552168 nid=0x7f96 waiting on condition [0x888ea000..0x888ead80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-44" prio=1 tid=0x89af3680 nid=0x7f95 waiting on condition [0x8896b000..0x8896be00]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-43" prio=1 tid=0x8afe1d38 nid=0x7f94 waiting on condition [0x88a6d000..0x88a6de80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:320)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:465)
      at java.lang.Thread.run(Thread.java:595)

      "qtp14633980-42 - Acceptor0 SelectChannelConnector@0.0.0.0:7922" prio=1 tid=0x89552d90 nid=0x7f93 runnable [0x889ec000..0x889ecf00]
      at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
      at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
      at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
      at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)

      • locked <0x90ca0a98> (a sun.nio.ch.Util$1)
      • locked <0x90ca0a88> (a java.util.Collections$UnmodifiableSet)
      • locked <0x90ca09b0> (a sun.nio.ch.PollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
        at org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:480)
        at org.eclipse.jetty.io.nio.SelectorManager.doSelect(SelectorManager.java:193)
        at org.eclipse.jetty.server.nio.SelectChannelConnector.accept(SelectChannelConnector.java:134)
        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:793)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:436)
        at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Transport Server: tcp://0.0.0.0:7921?transport.closeAsync=false" daemon prio=1 tid=0x898b32d0 nid=0x7f87 runnable [0x88c71000..0x88c72100]
      at java.net.PlainSocketImpl.socketAccept(Native Method)
      at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)

      • locked <0x90bac140> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at org.apache.activemq.transport.tcp.TcpTransportServer.run(TcpTransportServer.java:280)
        at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Transport Server Thread Handler: tcp://0.0.0.0:7921?transport.closeAsync=false" daemon prio=1 tid=0x8966b640 nid=0x7f86 waiting on condition [0x88cf2000..0x88cf2d80]
      at sun.misc.Unsafe.park(Native Method)
      at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:146)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
      at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:396)
      at org.apache.activemq.transport.tcp.TcpTransportServer$1.run(TcpTransportServer.java:352)
      at java.lang.Thread.run(Thread.java:595)

      "ActiveMQ Data File Writer" daemon prio=1 tid=0x89a21840 nid=0x7f84 in Object.wait() [0x88df4000..0x88df4e80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90ba1318> (a org.apache.kahadb.journal.DataFileAppender$1)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.kahadb.journal.DataFileAppender.processQueue(DataFileAppender.java:325)
      • locked <0x90ba1318> (a org.apache.kahadb.journal.DataFileAppender$1)
        at org.apache.kahadb.journal.DataFileAppender$2.run(DataFileAppender.java:216)

      "ActiveMQ Journal Checkpoint Worker" daemon prio=1 tid=0x898bf0b8 nid=0x7f83 waiting on condition [0x88e75000..0x88e75f00]
      at java.lang.Thread.sleep(Native Method)
      at org.apache.activemq.store.kahadb.MessageDatabase$3.run(MessageDatabase.java:286)

      "KahaDB Scheduler" daemon prio=1 tid=0x8c5d25c0 nid=0x7f82 in Object.wait() [0x88ef6000..0x88ef6f80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90ba0430> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
      • locked <0x90ba0430> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

      "RMI LeaseChecker" daemon prio=1 tid=0x8afe0d38 nid=0x7f7e waiting on condition [0x89079000..0x89079d80]
      at java.lang.Thread.sleep(Native Method)
      at sun.rmi.transport.DGCImpl$LeaseChecker.run(DGCImpl.java:310)
      at java.lang.Thread.run(Thread.java:595)

      "RMI RenewClean-[10.4.64.66:39231]" daemon prio=1 tid=0x0a337590 nid=0x7f7c in Object.wait() [0x8917b000..0x8917be80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90b9e178> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      • locked <0x90b9e178> (a java.lang.ref.ReferenceQueue$Lock)
        at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:501)
        at java.lang.Thread.run(Thread.java:595)

      "GC Daemon" daemon prio=1 tid=0x0a295dc0 nid=0x7f7a in Object.wait() [0x8927d000..0x8927df80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90c48fe8> (a sun.misc.GC$LatencyLock)
        at sun.misc.GC$Daemon.run(GC.java:100)
      • locked <0x90c48fe8> (a sun.misc.GC$LatencyLock)

      "RMI Reaper" prio=1 tid=0x0a295620 nid=0x7f79 in Object.wait() [0x892fe000..0x892ff000]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90ae27e0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      • locked <0x90ae27e0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
        at sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java:336)
        at java.lang.Thread.run(Thread.java:595)

      "RMI TCP Accept-0" daemon prio=1 tid=0x0a295040 nid=0x7f78 runnable [0x894fe000..0x894ff080]
      at java.net.PlainSocketImpl.socketAccept(Native Method)
      at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)

      • locked <0x90bc0380> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
        at java.lang.Thread.run(Thread.java:595)

      "RMI TCP Accept-7923" daemon prio=1 tid=0x898869b8 nid=0x7f76 runnable [0x8b2e2000..0x8b2e2d80]
      at java.net.PlainSocketImpl.socketAccept(Native Method)
      at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)

      • locked <0x90b9e450> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
        at java.lang.Thread.run(Thread.java:595)

      "RMI TCP Accept-0" daemon prio=1 tid=0x8be438c8 nid=0x7f6d runnable [0x8bcb7000..0x8bcb7e80]
      at java.net.PlainSocketImpl.socketAccept(Native Method)
      at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)

      • locked <0x90b27a40> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:31)
        at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
        at java.lang.Thread.run(Thread.java:595)

      "Timer-0" daemon prio=1 tid=0x8be41cc8 nid=0x7f6c in Object.wait() [0x8bd38000..0x8bd38f00]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90b27b28> (a java.util.TaskQueue)
        at java.lang.Object.wait(Object.java:474)
        at java.util.TimerThread.mainLoop(Timer.java:483)
      • locked <0x90b27b28> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

      "Low Memory Detector" daemon prio=1 tid=0x8c5cffe0 nid=0x7f6b runnable [0x00000000..0x00000000]

      "CompilerThread1" daemon prio=1 tid=0x8c5cec00 nid=0x7f6a waiting on condition [0x00000000..0x8c079228]

      "CompilerThread0" daemon prio=1 tid=0x8c5cdc80 nid=0x7f69 waiting on condition [0x00000000..0x8c0fa2a8]

      "AdapterThread" daemon prio=1 tid=0x8c5cccc0 nid=0x7f68 waiting on condition [0x00000000..0x00000000]

      "Signal Dispatcher" daemon prio=1 tid=0x8c5cbe88 nid=0x7f67 waiting on condition [0x00000000..0x00000000]

      "Finalizer" daemon prio=1 tid=0x8c5c2840 nid=0x7f66 in Object.wait() [0x8c47d000..0x8c47de00]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90b2a8e8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      • locked <0x90b2a8e8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

      "Reference Handler" daemon prio=1 tid=0x8c5c22f8 nid=0x7f65 in Object.wait() [0x8c4fe000..0x8c4fee80]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90b31778> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
      • locked <0x90b31778> (a java.lang.ref.Reference$Lock)

      "main" prio=1 tid=0x09b460c0 nid=0x7f58 in Object.wait() [0xbff23000..0xbff24758]
      at java.lang.Object.wait(Native Method)

      • waiting on <0x90d6bef0> (a [Z)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.activemq.console.command.StartCommand.waitForShutdown(StartCommand.java:161)
      • locked <0x90d6bef0> (a [Z)
        at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:104)
        at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
        at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:143)
        at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
        at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:85)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:592)
        at org.apache.activemq.console.Main.runTaskClass(Main.java:251)
        at org.apache.activemq.console.Main.main(Main.java:107)

      "VM Thread" prio=1 tid=0x8c5bff38 nid=0x7f64 runnable

      "GC task thread#0 (ParallelGC)" prio=1 tid=0x09b60ad0 nid=0x7f60 runnable

      "GC task thread#1 (ParallelGC)" prio=1 tid=0x09b61720 nid=0x7f61 runnable

      "GC task thread#2 (ParallelGC)" prio=1 tid=0x09b62358 nid=0x7f62 runnable

      "GC task thread#3 (ParallelGC)" prio=1 tid=0x09b62f90 nid=0x7f63 runnable

      "VM Periodic Task Thread" prio=1 tid=0x8be4cb40 nid=0x7f6e waiting on condition

      ----------

      INFO | The connection to '/10.4.64.66:36292' is taking a long time to shutdown.
      INFO | The connection to '/10.4.64.66:36292' is taking a long time to shutdown.
      INFO | The connection to '/10.4.64.66:36292' is taking a long time to shutdown.
      INFO | The connection to '/10.4.64.66:36292' is taking a long time to shutdown.

      ----------

      java 32600 scott 6u IPv6 19919590 0t0 TCP *:59822 (LISTEN)
      java 32600 scott 9u IPv6 19919615 0t0 TCP *:7923 (LISTEN)
      java 32600 scott 12u IPv6 19919617 0t0 TCP *:39231 (LISTEN)
      java 32600 scott 14u IPv6 20371784 0t0 TCP h1:7922->h2:48935 (ESTABLISHED)
      java 32600 scott 18u IPv6 20371785 0t0 TCP h1:7922->h2:48936 (ESTABLISHED)
      java 32600 scott 20u IPv6 20371786 0t0 TCP h1:7922->h2:48937 (ESTABLISHED)
      java 32600 scott 24u IPv6 20371787 0t0 TCP h1:7922->h2:48938 (ESTABLISHED)
      java 32600 scott 29u IPv6 19919657 0t0 TCP *:7922 (LISTEN)
      java 32600 scott 30u IPv6 20371788 0t0 TCP h1:7922->h2:48939 (ESTABLISHED)
      java 32600 scott 31u IPv6 20371789 0t0 TCP h1:7922->h2:48940 (ESTABLISHED)

      ----------

      <destinationPolicy>
      <policyMap>
      <policyEntries>
      <!-- By default, do not use the DLQ, and use vmcursors -->
      <policyEntry queue=">">
      <deadLetterStrategy>
      <sharedDeadLetterStrategy processExpired="false"/>
      </deadLetterStrategy>
      <pendingQueuePolicy>
      <vmQueueCursor/>
      </pendingQueuePolicy>
      </policyEntry>
      </policyEntries>
      </policyMap>
      </destinationPolicy>
      [...]
      <systemUsage>
      <systemUsage sendFailIfNoSpace="true">
      <memoryUsage>
      <memoryUsage limit="256 mb"/>
      </memoryUsage>
      <storeUsage>
      <storeUsage limit="1 gb" name="foo"/>
      </storeUsage>
      <tempUsage>
      <tempUsage limit="100 mb"/>
      </tempUsage>
      </systemUsage>
      </systemUsage>

      ----------

      rw-rr- 1 scott scott 36621377 2011-04-21 17:35 db-126.log
      rw-rr- 1 scott scott 37281079 2011-04-21 17:35 db-127.log
      rw-rr- 1 scott scott 33556041 2011-04-21 23:17 db-132.log
      rw-rr- 1 scott scott 33030144 2011-04-22 09:25 db-134.log
      rw-rr- 1 scott scott 53248 2011-04-22 09:25 db.data
      rw-rr- 1 scott scott 32824 2011-04-22 09:25 db.redo
      rw-rr- 1 scott scott 0 2011-04-21 17:17 lock

      du -sh on kahadb: 128M

      Attachments

        1. activemq.xml
          4 kB
          Scott Emmons
        2. jms.java
          3 kB
          Scott Emmons

        Issue Links

          depends upon

          Bug - A problem which impairs or prevents the functions of the product. AMQ-3357 vmQueueCursor or fileQueueCursor with expired messages in the store can lead to startup hang with kahaDB

          • Major - Major loss of function.
          • Resolved

          Activity

            People

              gtully Gary Tully
              scotte Scott Emmons
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: