[AMQ-5384] Deadlock on DB connections in JDBCMessageStore.removeMessage

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 5.9.0
• Fix Version/s: 5.11.0
• Component/s: Message Store

Environment

AMQ 5.9.0 with Oracle 11.2 as persistent store. C3P0 as conneciton pool.

• Assignee: Unassigned
• Reporter: Tomasz Skorka
• Created: 06/Oct/14 09:26
• Updated: 07/Dec/15 20:15
• Resolved: 07/Oct/14 14:56

Description

AMQ 5.9 gets stuck under 30-50 req/second load when using JDBC persistence - this affects our application as it hangs during performance testing (this happens almost every night).
Following stacktraces indicate that there's a deadlock on DB connection:

Stack logged by C3P0, showing when first DB connection has been picked from the pool:

2014-10-06 08:44:40,646 | INFO  | Logging the stack trace by which the overdue resource was checked-out. | com.mchange.v2.resourcepool.BasicResourcePool | C3P0PooledConnectionPoolManager[identityToken->2x1e6s941raztn6mju110
java.lang.Exception: DEBUG STACK TRACE: Overdue resource check-out stack trace.
        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:555)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:756)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:683)
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
        at org.apache.activemq.store.jdbc.TransactionContext.getConnection(TransactionContext.java:58)
        at org.apache.activemq.store.jdbc.TransactionContext.begin(TransactionContext.java:163)
        at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.beginTransaction(JDBCPersistenceAdapter.java:510)
        at org.apache.activemq.store.memory.MemoryTransactionStore$Tx.commit(MemoryTransactionStore.java:92)
        at org.apache.activemq.store.memory.MemoryTransactionStore.commit(MemoryTransactionStore.java:259)
        at org.apache.activemq.transaction.XATransaction.storeCommit(XATransaction.java:85)
        at org.apache.activemq.transaction.XATransaction.commit(XATransaction.java:75)
        at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:253)
        at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:112)
        at org.apache.activemq.broker.TransportConnection.processCommitTransactionTwoPhase(TransportConnection.java:433)
        at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:102)
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:270)
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
        at java.lang.Thread.run(Thread.java:662)

Following stack shows the same thread pending for second DB connection (without releasing the first one):

"ActiveMQ Transport: tcp:///10.132.7.20:36431@5445" daemon prio=10 tid=0x000000004119d000 nid=0x61bf in Object.wait() [0x00007f41120d7000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000fabdd2c0> (a com.mchange.v2.resourcepool.BasicResourcePool)
	at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1414)
	at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:606)
	- locked <0x00000000fabdd2c0> (a com.mchange.v2.resourcepool.BasicResourcePool)
	at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:526)
	at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:756)
	at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:683)
	at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
	at org.apache.activemq.store.jdbc.TransactionContext.getConnection(TransactionContext.java:58)
	at org.apache.activemq.store.jdbc.adapter.DefaultJDBCAdapter.getStoreSequenceId(DefaultJDBCAdapter.java:290)
	at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.getStoreSequenceIdForMessageId(JDBCPersistenceAdapter.java:840)
	at org.apache.activemq.store.jdbc.JDBCMessageStore.removeMessage(JDBCMessageStore.java:194)
	at org.apache.activemq.store.memory.MemoryTransactionStore$4.run(MemoryTransactionStore.java:348)
	at org.apache.activemq.store.memory.MemoryTransactionStore$Tx.commit(MemoryTransactionStore.java:103)
	at org.apache.activemq.store.memory.MemoryTransactionStore.commit(MemoryTransactionStore.java:259)
	at org.apache.activemq.transaction.XATransaction.storeCommit(XATransaction.java:85)
	at org.apache.activemq.transaction.XATransaction.commit(XATransaction.java:69)
	at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:253)
	at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:112)
	at org.apache.activemq.broker.TransportConnection.processCommitTransactionOnePhase(TransportConnection.java:424)
	at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:100)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:270)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
	at java.lang.Thread.run(Thread.java:662) 

Problem seems to be related with JDBCMessageStore.removeMessage method:

    public void removeMessage(ConnectionContext context, MessageAck ack) throws IOException {
    	long seq = persistenceAdapter.getStoreSequenceIdForMessageId(ack.getLastMessageId(), destination)[0];
...

Call to removeMessage already has one DB connection passed in context method parameter, but calling persistenceAdapter.getStoreSequenceIdForMessageId creates another DB connection in the same transaction.

Deadlock occurs when all DB connections are used by context, so that removeMessage can't fetch its own connection.

Possible solution would be to pass ConnectionContext object to persistenceAdapter.getStoreSequenceIdForMessageId method, so that the method would reuse same connection.

Issue Links

• duplicates: AMQ-4566 Broker hangs when forced to wait for DB connection from pool
• is related to: AMQ-4566 Broker hangs when forced to wait for DB connection from pool