Capturing MySQL Deadlock in MDB (ActiveMQ) in JBoss 5.1

Question

We use JBoss 5.1 w / MDB supported by ActiveMQ RAR.

When a message in the queue is consumed and performs some database operations, which then lead to a deadlock, the deadlock essentially throws the entire JBoss instance before it restarts. By hosed, any subsequent messages consumed in this queue fail, with the following exception:

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

The deadlock exception never refers to my code, which in turn makes it difficult for me to catch and process.

For example, here is a blocking exception 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.ar juna.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@2c9e90 6 handles=0 lastUse=1340059939649 permit=true trackByTx=true mcp=org.jbos s.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ 10015060 context=org .jboss.resource.connectionmanager.InternalManagedConnectionPool@ 4643d6d5 xa Resource=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 following errors (errors in subsequent messages in the queue):

Called: 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 won't work, but I get through Injection to start ... The only way I know to fix this is a restart error.

I assume that the initial "dead end" occurs as part of the completion of the transaction in the queue, so this does not happen in my code, but do I know how 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 solve this problem by isolating each transaction using the following method:

Annotate MDB:

  @TransactionManagement(value = TransactionManagementType.BEAN) 

Thus, telling MDB that the Bean itself will manage the transaction, not the container (outside my code), then enter the necessary resources:

  @Resource MessageDrivenContext mc; UserTransaction tx; 

Create and manage my own transactions

  tx = mc.getUserTransaction(); tx.begin(); //Do work tx.commit(); 

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

Using very granular transactions, I was able to track where a lock / race condition occurred in my code. As soon as I decided that I was able to undo some of the more competent transaction management.

Answer 2

Unable to handle container transaction exception.

It decides the rollback, regardless of the reason, and you have no control over it. A tricky way to get notified of such exceptions and rollback events is to record a JCA connector that registers fake resources in the Distributed Transaction Manager for each MDB transaction.

I would recommend that you research what is happening and fix the problem from my source.

Here is a deadlock scenario, it always includes several threads: if two code fragments use the same objects, but in a different order, the first thread blocks resource A (row, table or Java monitor) and wait B when the second thread has already blocked the resource B and now awaits A.

Thus, distributed deadlock is possible between Java monitors and database resources, and this case is difficult to diagnose. A complete system gets stuck until transaction timeouts at both ends, Java thread jumps, and database sessions and locks are verified.

In your case, since MySQL detects dead-lock itself, this means that only database resources are involved.

To help, I think you should reduce the number of SQL queries executed in a batch update for one JMS message, one transaction. With the simultaneous use of simultaneous messages working in a transaction with a large number of rows, the probability of a deadlock occurs more often.

But it’s strange that your JBoss server got stuck after rollback due to deadlock for DB only:

• either you have exhausted the number of JDBC connections from the DataSource pool
• or there is no longer a connection to the server side of MySQL
• or all beans messages are also in a blocking situation.
• transaction timeout may be too high to receive rollbacks in a reasonable amount of time

Thus, either you reduce the MDB concurrency by reducing the size of the corresponding pool, or reduce the number of updates per transaction - maybe even one update per JMS message ...