Bug 777600 (SOA-109)

Summary: Transaction deadlock in messaging
Product: [JBoss] JBoss Enterprise SOA Platform 4 Reporter: Martin Vecera <mvecera>
Component: JBossESBAssignee: Kevin Conner <kevin.conner>
Status: CLOSED WONTFIX QA Contact:
Severity: high Docs Contact:
Priority: high    
Version: 4.2 IR4   
Target Milestone: ---   
Target Release: 4.2 IR6   
Hardware: Unspecified   
OS: Unspecified   
URL: http://jira.jboss.org/jira/browse/SOA-109
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
soa-standalone, MySQL 5.0.22 (transaction-isolation: TRANSACTION_READ_COMMITTED - as suggested at server startup), Sun JVM 1.5.0
Last Closed: 2007-11-15 13:44:46 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Martin Vecera 2007-11-08 10:58:13 UTC 
Date of First Response: 2007-11-08 11:35:53
project_key: SOA

I started performance test 1 (from https://svn.corp.jboss.com/repos/soa/trunk/qa/tests) with the following parameters:
ant executeng -Dtestng.filter=Performance1Test -Dtest.performance.messagecount=2000000 -Dtest.performance.messagefile=5KB_message.xml -Dtest.performance.sender=jms -Dtest.performance.speed=optimized

This should have found an optimal load of messages. The ESB was consuming the message with speed around 108 msg/s. After ~3 hours of testing it started having problems with transaction deadlock:

2007-11-07 21:15:27,540 WARN  [org.jboss.messaging.core.impl.JDBCSupport] SQLException caught, SQLState HY000 code:1206- assuming deadlock detected, try:1
java.sql.SQLException: The total number of locks exceeds the lock table size
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1585)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1500)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1485)
        at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$1ReaperRunner.doTransaction(JDBCPersistenceManager.java:2344)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.execute(JDBCSupport.java:385)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.executeWithRetry(JDBCSupport.java:407)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.reapUnreferencedMessages(JDBCPersistenceManager.java:2357)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.access$1000(JDBCPersistenceManager.java:78)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$Reaper.run(JDBCPersistenceManager.java:2381)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)
2007-11-07 21:15:27,583 WARN  [org.jboss.messaging.core.impl.JDBCSupport] Trying again after a pause
2007-11-07 21:15:53,908 WARN  [org.jboss.messaging.core.impl.JDBCSupport] SQLException caught, SQLState HY000 code:1206- assuming deadlock detected, try:2
java.sql.SQLException: The total number of locks exceeds the lock table size
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1585)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1500)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1485)
        at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$1ReaperRunner.doTransaction(JDBCPersistenceManager.java:2344)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.execute(JDBCSupport.java:385)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.executeWithRetry(JDBCSupport.java:407)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.reapUnreferencedMessages(JDBCPersistenceManager.java:2357)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.access$1000(JDBCPersistenceManager.java:78)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$Reaper.run(JDBCPersistenceManager.java:2381)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)
2007-11-07 21:15:53,973 WARN  [org.jboss.messaging.core.impl.JDBCSupport] Trying again after a pause

...
2007-11-07 21:16:22,972 WARN  [org.jboss.messaging.core.impl.JDBCSupport] SQLException caught, SQLState HY000 code:1206- assuming deadlock detected, try:1
java.sql.SQLException: The total number of locks exceeds the lock table size
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1585)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1500)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1485)
        at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$1AddReferenceRunner.doTransaction(JDBCPersistenceManager.java:1196)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.execute(JDBCSupport.java:385)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.executeWithRetry(JDBCSupport.java:407)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.addReference(JDBCPersistenceManager.java:1226)
        at org.jboss.messaging.core.impl.ChannelSupport.handleInternal(ChannelSupport.java:616)
        at org.jboss.messaging.core.impl.ChannelSupport.handle(ChannelSupport.java:144)
        at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.routeInternal(MessagingPostOffice.java:2122)
        at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.route(MessagingPostOffice.java:478)
        at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendMessage(ServerConnectionEndpoint.java:703)
        at org.jboss.jms.server.endpoint.ServerSessionEndpoint.send(ServerSessionEndpoint.java:343)
        at org.jboss.jms.server.endpoint.advised.SessionAdvised.org$jboss$jms$server$endpoint$advised$SessionAdvised$send$aop(SessionAdvised.java:80)
        at org.jboss.jms.server.endpoint.advised.SessionAdvised$send_6145266547759487588.invokeNext(SessionAdvised$send_6145266547759487588.java)
        at org.jboss.jms.server.container.SecurityAspect.handleSend(SecurityAspect.java:157)
        at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
        at org.jboss.jms.server.endpoint.advised.SessionAdvised$send_6145266547759487588.invokeNext(SessionAdvised$send_6145266547759487588.java)
        at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
        at org.jboss.jms.server.endpoint.advised.SessionAdvised$send_6145266547759487588.invokeNext(SessionAdvised$send_6145266547759487588.java)
        at org.jboss.jms.server.endpoint.advised.SessionAdvised.send(SessionAdvised.java)
        at org.jboss.jms.wireformat.SessionSendRequest.serverInvoke(SessionSendRequest.java:85)
        at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:144)
        at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:771)
        at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:101)
        at org.jboss.remoting.Client.invoke(Client.java:1634)
        at org.jboss.remoting.Client.invoke(Client.java:548)
        at org.jboss.remoting.Client.invoke(Client.java:536)
        at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:186)
        at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:157)
        at org.jboss.jms.client.delegate.ClientSessionDelegate.org$jboss$jms$client$delegate$ClientSessionDelegate$send$aop(ClientSessionDelegate.java:447)
        at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java)
        at org.jboss.jms.client.container.SessionAspect.handleSend(SessionAspect.java:631)
        at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect28.invoke(SessionAspect28.java)
        at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java)
        at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:91)
        at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
        at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java)
        at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
        at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
        at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java)
        at org.jboss.jms.client.delegate.ClientSessionDelegate.send(ClientSessionDelegate.java)
        at org.jboss.jms.client.container.ProducerAspect.handleSend(ProducerAspect.java:266)
        at org.jboss.aop.advice.org.jboss.jms.client.container.ProducerAspect46.invoke(ProducerAspect46.java)
        at org.jboss.jms.client.delegate.ClientProducerDelegate$send_3961598017717988886.invokeNext(ClientProducerDelegate$send_3961598017717988886.java)
        at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
        at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
        at org.jboss.jms.client.delegate.ClientProducerDelegate$send_3961598017717988886.invokeNext(ClientProducerDelegate$send_3961598017717988886.java)
        at org.jboss.jms.client.delegate.ClientProducerDelegate.send(ClientProducerDelegate.java)
        at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:164)
        at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:207)
        at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:145)
        at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:136)
        at org.jboss.internal.soa.esb.couriers.JmsCourier.sendMessage(JmsCourier.java:267)
        at org.jboss.internal.soa.esb.couriers.JmsCourier.deliver(JmsCourier.java:242)
        at org.jboss.internal.soa.esb.couriers.JmsCourier.deliver(JmsCourier.java:210)
        at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.deliver(TwoWayCourierImpl.java:188)
        at org.jboss.soa.esb.listeners.gateway.JmsGatewayListener.doRun(JmsGatewayListener.java:172)
        at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115)
        at java.lang.Thread.run(Thread.java:595)

After several hours I returned back to the machine and it was still showing these errors:
2007-11-08 08:52:41,075 WARN  [org.jboss.messaging.core.impl.JDBCSupport] SQLException caught, SQLState HY000 code:1206- assuming deadlock detected, try:24
java.sql.SQLException: The total number of locks exceeds the lock table size
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1585)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1500)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1485)
        at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$1ReaperRunner.doTransaction(JDBCPersistenceManager.java:2344)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.execute(JDBCSupport.java:385)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.executeWithRetry(JDBCSupport.java:407)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.reapUnreferencedMessages(JDBCPersistenceManager.java:2357)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.access$1000(JDBCPersistenceManager.java:78)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$Reaper.run(JDBCPersistenceManager.java:2381)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)
2007-11-08 08:52:41,076 WARN  [org.jboss.messaging.core.impl.JDBCSupport] Trying again after a pause
2007-11-08 08:53:15,241 WARN  [org.jboss.messaging.core.impl.JDBCSupport] SQLException caught, SQLState HY000 code:1206- assuming deadlock detected, try:25
java.sql.SQLException: The total number of locks exceeds the lock table size
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2985)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1585)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1500)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1485)
        at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:251)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$1ReaperRunner.doTransaction(JDBCPersistenceManager.java:2344)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.execute(JDBCSupport.java:385)
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.executeWithRetry(JDBCSupport.java:407)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.reapUnreferencedMessages(JDBCPersistenceManager.java:2357)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.access$1000(JDBCPersistenceManager.java:78)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$Reaper.run(JDBCPersistenceManager.java:2381)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)
2007-11-08 08:53:15,241 ERROR [org.jboss.messaging.core.impl.JDBCSupport] Retried 25 times, now giving up
2007-11-08 08:53:15,241 ERROR [org.jboss.messaging.core.impl.JDBCPersistenceManager] Failed to reap
java.lang.IllegalStateException: Failed to excecute transaction
        at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner.executeWithRetry(JDBCSupport.java:423)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.reapUnreferencedMessages(JDBCPersistenceManager.java:2357)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager.access$1000(JDBCPersistenceManager.java:78)
        at org.jboss.messaging.core.impl.JDBCPersistenceManager$Reaper.run(JDBCPersistenceManager.java:2381)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)
Comment 1 Mark Little 2007-11-08 16:35:53 UTC 
Can you try this test with JBM in isolation, so we can see if it's an issue with ESB or JBM?
Comment 2 Martin Vecera 2007-11-14 10:50:21 UTC 
Deadlocks are still there in soa-standalone IR5 :-(
Comment 3 Kevin Conner 2007-11-14 10:56:35 UTC 
Martin, can you send me a server.log from one of these please?

Thanks
Comment 4 Martin Vecera 2007-11-14 14:37:51 UTC 
I need to recreate it. What level of detail you need? I'll let it run through the night...
Comment 5 Mark Little 2007-11-14 21:47:21 UTC 
Check http://mrothouse.wordpress.com/2006/10/20/mysql-error-1206/ as well.
Comment 6 Mark Little 2007-11-14 21:49:38 UTC 
Oh, and http://lists.mysql.com/mysql/193440
Comment 7 Martin Vecera 2007-11-15 13:44:28 UTC 
The problem was caused by MySQL lock table overflow. Increasing it's size solved the problem. Thanks for useful comments!