Catching MySQL Deadlocks in a MDB (ActiveMQ) in JBoss 5.1

Question

We are using JBoss 5.1 w/ MDB backed by ActiveMQ RAR.

When a message on a queue is consumed and performs some database operations which then result in a deadlock, the deadlock is essentially hosing the entire instance of JBoss until it is restarted. By hosed, any subsequent messages consumed on that queue all fail with the follow exception:

Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection

The deadlock exception never references my code, which in turn make it very difficult for me to catch and handle.

For example, here is an exception of a deadlock exception:

2012-06-18 18:52:19,848 WARN   [JDBCExceptionReporter] : SQL Error: 1213, SQLState: 40001
2012-06-18 18:52:19,848 ERROR  [JDBCExceptionReporter] : Deadlock found when trying to get lock; try restarting transaction
2012-06-18 18:52:19,850 ERROR  [AbstractFlushingEventListener] : Could not synchronize database state with session
org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
        at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
        at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:504)
        at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:269)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:89)
        at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:435)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:314)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:230)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:136)
        at $Proxy677.afterDelivery(Unknown Source)
        at org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)
        at org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)
        at org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)
        at org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)
        at org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
        at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
        at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2013)
        at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
        at com.mysql.jdbc.jdbc2.optional.StatementWrapper.executeBatch(StatementWrapper.java:721)
        at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
        ... 29 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:407)
        at com.mysql.jdbc.Util.getInstance(Util.java:382)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1064)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3603)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3535)
         at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1989)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2150)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2626)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
        ... 34 more
2012-06-18 18:52:19,851 WARN   [arjLoggerI18N] : [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@480671ab
javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:614)
        at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:513)
        at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:269)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:89)
        at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:435)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:314)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:230)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:136)
        at $Proxy677.afterDelivery(Unknown Source)
        at org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)
        at org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)
        at org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)
        at org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)
        at org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
        at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
        at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
Caused by: org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:105)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
        at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
        at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:504)
        ... 22 more
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2013)
        at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
        at com.mysql.jdbc.jdbc2.optional.StatementWrapper.executeBatch(StatementWrapper.java:721)
        at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
        ... 29 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
                at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:407)
        at com.mysql.jdbc.Util.getInstance(Util.java:382)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1064)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3603)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3535)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1989)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2150)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2626)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
        ... 34 more
2012-06-18 18:52:19,912 WARN   [TxConnectionManager] : Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@6acc2da9[state=NORMAL mc=org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@2c9e906 handles=0 lastUse=1340059939649 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@10015060 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@4643d6d5 xaResource=org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@2c9e906 txSync=null]
com.mysql.jdbc.jdbc2.optional.MysqlXAException: XA_RBDEADLOCK: Transaction branch was rolled back: deadlock was detected
        at com.mysql.jdbc.jdbc2.optional.MysqlXAConnection.mapXAExceptionFromSQLException(MysqlXAConnection.java:605)
        at com.mysql.jdbc.jdbc2.optional.MysqlXAConnection.dispatchCommand(MysqlXAConnection.java:584)
        at com.mysql.jdbc.jdbc2.optional.MysqlXAConnection.end(MysqlXAConnection.java:479)
        at org.jboss.resource.adapter.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:246)
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:396)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3270)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3248)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1933)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:97)
        at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:435)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:314)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:230)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:136)
        at $Proxy677.afterDelivery(Unknown Source)
        at org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)
        at org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)
        at org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)
        at org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)
        at org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
        at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
        at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
2012-06-18 18:52:19,914 INFO   [ServerSessionImpl:153] : Endpoint failed to process message. Reason: Endpoint after delivery notification failure

I can catch the subsequent errors (the errors on subsequent messages to the queue):

Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection

But I'm not even sure what to do with it, maybe I can get a new EntityManager that isn't hosed, but I'm getting via Injection to begin with... The only way I know to fix this error is to restart.

I assume that the initial Deadlock is happening as part of ending the transaction in the Queue which is why it's not happening in my code, but does any idea of a way I can handle this gracefully?

Update:

• All DataSources are MySQL XA
• In transaction-jboss-beans.xml we have transactionTimeout set to 300

Answer 1

I was able to resolve this by isolating each transaction using the following method:

Annotate the MDB with:

    @TransactionManagement(value = TransactionManagementType.BEAN)

Thus telling the MDB that the Bean itself will manage the transaction and not the container (outside of my code), next, inject the necessary resources:

    @Resource
    MessageDrivenContext mc;
    UserTransaction tx;

To create and manage my own transactions

    tx = mc.getUserTransaction();
    tx.begin();

    //Do work

    tx.commit();

The above step can be repeated for each block of code.

Using very granular transactions I was able to trace where in my code the lock / race condition was happening. Once I solved that I was able to back out some of the more granular transaction management.

Answer 2

There is no way to handle container transaction exception gracefully.

It decides to rollback whatever the reason is and you have no control against it. A complex option to get notified about such exceptions and rollback events may be to write a JCA connector which enrolls fake resources into the distributed transaction manager for each MDB transaction.

I would recommend you to investigate what happens and fix the trouble from its source.

Here is a dead-lock scenario, it always involve multiple threads: if two pieces of code use the same entities but in different order, a first thread will lock resource A (a row, a table or a Java monitor) and wait for B when a second thread have already locked resource B and now waits for A.

So a distributed dead-lock is possible between Java monitors and Database resources and that case is complex to diagnose. The full system is stuck until the transaction timeouts at both ends, Java thread dumps and database sessions and locks must be scanned.

In your case, as MySQL detects the dead-lock itself, it means only database resources are involved.

To help, I guess you should reduce the number of SQL queries run in your batch update for one JMS message, one transaction. With concurrent messages consumed at the same time, working on transaction applying large number of rows, a deadlock situation is more likely to occur.

But it is strange that your JBoss server is stuck after rollback because of a DB-only dead-lock:

• either you have exhausted the number of JDBC connections from the DataSource pool
• or there is no more MySQL server-side connection available
• or all message beans are in dead-lock situation too
• the transaction timeout may be too high to get rollbacks in a reasonable time frame

So either you reduce MDB concurrency by down sizing the corresponding pool, either you reduce the number of updates per transaction - maybe even as small as one update per JMS message...