9 Replies Latest reply on Feb 1, 2005 1:55 PM by Scott Stark

    Persistence-related exceptions in JMS under heavy load

    ironbeard Newbie

      I've configured JMS to use Sybase for persistence. So far, I haven't
      seen any problems during extended periods of light to moderate
      message load (less than about 100 messages per second). However
      once the load increases beyond that, deadlocks start getting thrown.
      The most common example is a deadlock when trying to remove a
      message from the database.

      I'm running JBoss 3.2.5 on a 2.6GHz P4 with 1GB RAM.

      Any ideas on what might be the problem or what additional code to
      trace in order to track this down?


      2004-09-14 15:40:31,203 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 7095 msg=7094 hard NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=23303614
      2004-09-14 15:40:31,203 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 7095 msg=7094 hard STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=23303614
      2004-09-14 15:40:31,203 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 7096 msg=7095 hard NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=1239683
      2004-09-14 15:40:31,203 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 7096 msg=7095 hard STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=1239683
      2004-09-14 15:40:31,203 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-6:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7096 msg=7095 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=1239683
      2004-09-14 15:40:31,203 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-6:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message from storage 7096 msg=7095 soft NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=1239683
      2004-09-14 15:40:31,218 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7093 msg=7092 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=4567081
      2004-09-14 15:40:31,218 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message from storage 7093 msg=7092 soft NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=4567081
      2004-09-14 15:40:31,296 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 7097 msg=7096 hard NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=9821542
      2004-09-14 15:40:31,312 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-13:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7092 msg=7091 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=2637397
      2004-09-14 15:40:31,312 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 7097 msg=7096 hard STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=9821542
      2004-09-14 15:40:31,312 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-13:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message from storage 7092 msg=7091 soft NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=2637397
      2004-09-14 15:40:31,343 TRACE (Thread-63:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 7098 msg=7097 hard NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=12847905
      2004-09-14 15:40:31,343 TRACE (Thread-63:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 7098 msg=7097 hard STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=12847905
      2004-09-14 15:40:31,343 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-2:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7095 msg=7094 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=23303614
      2004-09-14 15:40:31,359 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-5:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7097 msg=7096 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=9821542
      2004-09-14 15:40:31,359 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-2:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message from storage 7095 msg=7094 soft NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=23303614
      2004-09-14 15:40:31,359 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-9:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7098 msg=7097 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=12847905
      2004-09-14 15:40:31,359 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-9:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message from storage 7098 msg=7097 soft NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=12847905
      2004-09-14 15:40:31,359 TRACE (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-10:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message from storage 7094 msg=7093 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=27444943
      2004-09-14 15:40:31,375 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 7099 msg=7098 hard NOT_STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=9032593
      2004-09-14 15:40:31,390 TRACE (Thread-12:) [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 7099 msg=7098 hard STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=9032593
      2004-09-14 15:40:31,390 ERROR (org.jboss.jms.asf.StdServerSessionPool$DefaultThreadFactory@14d8a08 Thread Pool Worker-5:) [org.jboss.mq.server.BasicQueue] Could not remove an acknowleged message from the message cache:
      org.jboss.mq.SpyJMSException: Could not remove message: 7097 msg=7096 soft STORED PERSISTENT queue=TOPIC.deviceManager.ID:4.-2147483648 priority=4 lateClone=false hashCode=9821542; - nested throwable: (com.sybase.jdbc2.jdbc.SybSQLException: ASA Error -306: Deadlock detected)
       at org.jboss.mq.pm.jdbc2.PersistenceManager.removeFromStorage(PersistenceManager.java:1163)
       at org.jboss.mq.server.MessageCache.removeFromStorage(MessageCache.java:390)
       at org.jboss.mq.server.MessageReference.clear(MessageReference.java:266)
       at org.jboss.mq.server.MessageCache.removeInternal(MessageCache.java:195)
       at org.jboss.mq.server.MessageCache.remove(MessageCache.java:153)
       at org.jboss.mq.server.BasicQueue$RemoveMessageTask.run(BasicQueue.java:1071)
       at org.jboss.mq.pm.Tx.commit(Tx.java:159)
       at org.jboss.mq.pm.TxManager.commitTx(TxManager.java:89)
       at org.jboss.mq.server.JMSDestinationManager.transact(JMSDestinationManager.java:440)
       at org.jboss.mq.server.JMSServerInterceptorSupport.transact(JMSServerInterceptorSupport.java:186)
       at org.jboss.mq.security.ServerSecurityInterceptor.transact(ServerSecurityInterceptor.java:182)
       at org.jboss.mq.server.TracingInterceptor.transact(TracingInterceptor.java:438)
       at org.jboss.mq.server.JMSServerInvoker.transact(JMSServerInvoker.java:186)
       at org.jboss.mq.il.jvm.JVMServerIL.transact(JVMServerIL.java:327)
       at org.jboss.mq.Connection.send(Connection.java:1206)
       at org.jboss.mq.SpyXAResourceManager.commit(SpyXAResourceManager.java:150)
       at org.jboss.mq.SpyXAResource.commit(SpyXAResource.java:84)
       at org.jboss.tm.TransactionImpl.commitResources(TransactionImpl.java:1656)
       at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:375)
       at org.jboss.tm.TxManager.commit(TxManager.java:142)
       at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:361)
       at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:871)
       at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:159)
       at org.jboss.mq.SpySession.run(SpySession.java:347)
       at org.jboss.jms.asf.StdServerSession.run0(StdServerSession.java:200)
       at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:180)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
       at java.lang.Thread.run(Thread.java:534)
      Caused by: com.sybase.jdbc2.jdbc.SybSQLException: ASA Error -306: Deadlock detected
       at com.sybase.jdbc2.tds.Tds.processEed(Tds.java:2834)
       at com.sybase.jdbc2.tds.Tds.nextResult(Tds.java:2156)
       at com.sybase.jdbc2.jdbc.ResultGetter.nextResult(ResultGetter.java:69)
       at com.sybase.jdbc2.jdbc.SybStatement.nextResult(SybStatement.java:220)
       at com.sybase.jdbc2.jdbc.SybStatement.nextResult(SybStatement.java:203)
       at com.sybase.jdbc2.jdbc.SybStatement.updateLoop(SybStatement.java:1702)
       at com.sybase.jdbc2.jdbc.SybStatement.executeUpdate(SybStatement.java:1685)
       at com.sybase.jdbc2.jdbc.SybPreparedStatement.executeUpdate(SybPreparedStatement.java:104)
       at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:335)
       at org.jboss.mq.pm.jdbc2.PersistenceManager.removeFromStorage(PersistenceManager.java:1154)
       ... 27 more