Deadlock between FilePendingMessageCursor and MemoryUsage

• Key: AMQ-1467
• Type: Bug
• Status: Resolved
• Resolution: Fixed
• Priority: Critical
• Assignee: Rob Davies
• Reporter: Nicky Sandhu
• Component/s: Broker
• Fix Version/s: 5.0.0

Description

Deadlock detected by jconsole. Fairly easy to reproduce with a maven-perf-test-plugin using journaled jdbc persistence. Using the latest 5.0-SNAPSHOT build

ActiveMQ Task
Name: ActiveMQ Task
State: BLOCKED on java.lang.Object@1ba1894 owned by: ActiveMQ Transport: tcp:///167.235.7.27:4215
Total blocked: 1,001 Total waited: 1,002

Stack trace:
org.apache.activemq.usage.MemoryUsage.increaseUsage(MemoryUsage.java:126)
org.apache.activemq.usage.MemoryUsage.increaseUsage(MemoryUsage.java:122)
org.apache.activemq.command.Message.incrementReferenceCount(Message.java:585)
org.apache.activemq.broker.region.cursors.FilePendingMessageCursor.next(FilePendingMessageCursor.java:198)

• locked org.apache.activemq.broker.region.cursors.FilePendingMessageCursor@1347d75
  org.apache.activemq.broker.region.cursors.StoreQueueCursor.next(StoreQueueCursor.java:129)
• locked org.apache.activemq.broker.region.cursors.StoreQueueCursor@14f3d22
  org.apache.activemq.broker.region.Queue.buildList(Queue.java:1020)
• locked org.apache.activemq.broker.region.cursors.StoreQueueCursor@14f3d22
• locked org.apache.activemq.broker.region.Queue@1b2591c
  org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1002)
  org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1065)
  org.apache.activemq.broker.region.Queue.iterate(Queue.java:938)
  org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:118)
  org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:42)
  java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
  java.lang.Thread.run(Thread.java:619)

ActiveMQ Transport: tcp://....:xxxx
Name: ActiveMQ Transport: tcp:///167.235.7.27:4215
State: BLOCKED on org.apache.activemq.broker.region.cursors.FilePendingMessageCursor@1347d75 owned by: ActiveMQ Task
Total blocked: 46 Total waited: 2

Stack trace:
org.apache.activemq.broker.region.cursors.FilePendingMessageCursor.onUsageChanged(FilePendingMessageCursor.java:260)
org.apache.activemq.usage.Usage.fireEvent(Usage.java:254)
org.apache.activemq.usage.Usage.setPercentUsage(Usage.java:224)

• locked java.lang.Object@1ba1894
  org.apache.activemq.usage.MemoryUsage.decreaseUsage(MemoryUsage.java:149)
  org.apache.activemq.usage.MemoryUsage.decreaseUsage(MemoryUsage.java:142)
  org.apache.activemq.command.Message.decrementReferenceCount(Message.java:601)
• locked org.apache.activemq.command.ActiveMQTextMessage@960b08
  org.apache.activemq.broker.region.IndirectMessageReference.drop(IndirectMessageReference.java:137)
• locked org.apache.activemq.broker.region.IndirectMessageReference@ae7918
  org.apache.activemq.broker.region.QueueSubscription.acknowledge(QueueSubscription.java:56)
  org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:193)
• locked org.apache.activemq.broker.region.QueueSubscription@1e13a2c
  org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:340)
  org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:427)
  org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:194)
  org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:73)
  org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:73)
  org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87)
  org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:478)
  org.apache.activemq.command.MessageAck.visit(MessageAck.java:196)
  org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:319)
  org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:216)
  org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:67)
  org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:134)
  org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:124)
• locked org.apache.activemq.transport.InactivityMonitor$1@10e2558
  org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
  org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:183)
  org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:170)
  java.lang.Thread.run(Thread.java:619)

Comments

[Nicky Sandhu]

The above stack trace could not be correlated to revision number. here's the stack trace with activemq-core revision # 585186
----------------- Thread : ActiveMQ Task ----------------------------------
Name: ActiveMQ Task
State: BLOCKED on java.lang.Object@fcc6e8 owned by: ActiveMQ Transport: tcp:///167.235.7.27:4773
Total blocked: 4,249 Total waited: 4,257

Stack trace:
org.apache.activemq.usage.MemoryUsage.decreaseUsage(MemoryUsage.java:146)
org.apache.activemq.usage.MemoryUsage.decreaseUsage(MemoryUsage.java:142)
org.apache.activemq.command.Message.decrementReferenceCount(Message.java:602)

• locked org.apache.activemq.command.ActiveMQTextMessage@450ae7
  org.apache.activemq.broker.region.cursors.FilePendingMessageCursor.remove(FilePendingMessageCursor.java:209)
• locked org.apache.activemq.broker.region.cursors.FilePendingMessageCursor@166c37e
  org.apache.activemq.broker.region.cursors.StoreQueueCursor.remove(StoreQueueCursor.java:135)
• locked org.apache.activemq.broker.region.cursors.StoreQueueCursor@cece16
  org.apache.activemq.broker.region.Queue.buildList(Queue.java:1021)
• locked org.apache.activemq.broker.region.cursors.StoreQueueCursor@cece16
• locked org.apache.activemq.broker.region.Queue@156f770
  org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1002)
  org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1065)
  org.apache.activemq.broker.region.Queue.iterate(Queue.java:938)
  org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:118)
  org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:42)
  java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
  java.lang.Thread.run(Thread.java:619)

------------------ Thread ActiveMQ Transport ---------------------------------------
Name: ActiveMQ Transport: tcp:///167.235.7.27:4773
State: BLOCKED on org.apache.activemq.broker.region.cursors.FilePendingMessageCursor@166c37e owned by: ActiveMQ Task
Total blocked: 69 Total waited: 0

Stack trace:
org.apache.activemq.broker.region.cursors.FilePendingMessageCursor.onUsageChanged(FilePendingMessageCursor.java:260)
org.apache.activemq.usage.Usage.fireEvent(Usage.java:254)
org.apache.activemq.usage.Usage.setPercentUsage(Usage.java:224)

• locked java.lang.Object@fcc6e8
  org.apache.activemq.usage.MemoryUsage.decreaseUsage(MemoryUsage.java:149)
  org.apache.activemq.usage.MemoryUsage.decreaseUsage(MemoryUsage.java:142)
  org.apache.activemq.command.Message.decrementReferenceCount(Message.java:602)
• locked org.apache.activemq.command.ActiveMQTextMessage@13c2797
  org.apache.activemq.broker.region.IndirectMessageReference.drop(IndirectMessageReference.java:137)
• locked org.apache.activemq.broker.region.IndirectMessageReference@4b5011
  org.apache.activemq.broker.region.QueueSubscription.acknowledge(QueueSubscription.java:56)
  org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:193)
• locked org.apache.activemq.broker.region.QueueSubscription@5cb0bb
  org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:340)
  org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:427)
  org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:194)
  org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:73)
  org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:73)
  org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87)
  org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:440)
  org.apache.activemq.command.MessageAck.visit(MessageAck.java:196)
  org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:281)
  org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:178)
  org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:67)
  org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:134)
  org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:124)
• locked org.apache.activemq.transport.InactivityMonitor$1@1b8b810
  org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
  org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:183)
  org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:170)
  java.lang.Thread.run(Thread.java:619)

[Nicky Sandhu]

Taking a page from the Swing/AWT event dispatch book I started a new thread for actually notifiying the listeners. This avoids this and other potential callback deadlocks for Usage.

Reran the load tests using maven-perftest-plugin and things seem to be stable so far

[Rob Davies]

Fixed by svn revision 585967

[Nicky Sandhu]

Deadlocked again.... I uncommented these lines @ line # 272 in Usage.java
getExecutor().execute(listenerNotifier);

And now it seems to work great. Please fix.

[Rob Davies]

DOH! can't believe I did that! - I was chasing down another bug

[Rob Davies]

svn revision 586581