Bug 777600 (SOA-109) - Transaction deadlock in messaging
Summary: Transaction deadlock in messaging
Keywords:
Status: CLOSED WONTFIX
Alias: SOA-109
Product: JBoss Enterprise SOA Platform 4
Classification: JBoss
Component: JBossESB
Version: 4.2 IR4
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 4.2 IR6
Assignee: Kevin Conner
QA Contact:
URL: http://jira.jboss.org/jira/browse/SOA...
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2007-11-08 10:58 UTC by Martin Vecera
Modified: 2007-11-15 13:44 UTC (History)
0 users

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
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

Attachments (Terms of Use)
Add an attachment (proposed patch, testcase, etc.)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker SOA-109 0 Major Closed Transaction deadlock in messaging 2018-03-21 03:01:20 UTC

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!
Note You need to log in before you can comment on or make changes to this bug.