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

Persistence-related exceptions in JMS under heavy load

ironbeard Sep 14, 2004 7:57 PM

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

1. Re: Persistence-related exceptions in JMS under heavy load

genman Sep 14, 2004 10:18 PM (in response to ironbeard)

Presumably, two threads using the persistence manager is causing interference in adding/removing transactions. I haven't seen this error before for other database vendors, but it may yet be valid. Is there some way you can get more detail messages on the lock situation? How are the tables being created?

Looks like "Thread Pool Worker-5" is waiting to do its delete, then fails. Perhaps the DB is anticipating the commit of the inserts as part of transaction to be completed by "(Thread-63:)" before doing its delete? (If that's the case, I'm curious how a message gets deleted before all inserts of the previous transaction complete.)

I wonder what Adrian thinks of this.
Actions
2. Re: Persistence-related exceptions in JMS under heavy load

ironbeard Sep 15, 2004 5:47 PM (in response to ironbeard)

How are the tables being created?

The JMS tables are manually created to match the commands defined in
sybase-jdb2-service.xml from the JBoss examples, and
hsqldb-jdbc-state-service.xml (which I modified to access my Sybase
datasource).

In addition, based on the recommendation in the WIKI, I added an
index on JMS_MESSAGES(TXID,TXOP). Somehow, that seems to be the
source of the problem. Earlier today, I got to wondering what would
happen if I removed this secondary index. And I haven't seen that
exception -- or any other -- out of JMS since. Apparently, Sybase has a
problem with the way that table is used if that index exists. ?!!

I'm continuing testing WITHOUT the index to see if the problem reappears.
Actions
3. Re: Persistence-related exceptions in JMS under heavy load

genman Sep 15, 2004 9:59 PM (in response to ironbeard)

Could you file a bug if you find something conclusive?
Actions
4. Re: Persistence-related exceptions in JMS under heavy load

eranha1 Jan 25, 2005 2:02 PM (in response to ironbeard)

This problem happens also in 3.2.6
I have opened a JIRA issue at : http://jira.jboss.com/jira/browse/JBMESSAGING-20

Please advice, we need to go to production with this application ASAP.
Actions
5. Re: Persistence-related exceptions in JMS under heavy load

adrian.brock Jan 28, 2005 3:17 PM (in response to ironbeard)

This looks like a similar problem to the FAQ with MSSQL.

If the database is holding locks that are not row locks, deadlocks are possible.

I don't see how the creation of lack of indices within the DB can be a JBoss problem?
Actions
6. Re: Persistence-related exceptions in JMS under heavy load

med_soft Jan 31, 2005 2:41 PM (in response to ironbeard)
I experienced the same deadlock problems you described, which tend to show up more under load. I discovered that row level locking in Sybase 11 & 12 is not always enabled/displayed properly by 3rd party database tools. The default seems to be to lock the entire table even when MAX_ROWS_PER_PAGE is set to one. You also have to make sure that "LOCK DATAROWS" is specified. The solution I found was to issue the following SQL commands:

ALTER TABLE JMS_MESSAGES LOCK DATAROWS ALTER TABLE JMS_TRANSACTIONS LOCK DATAROWS --which should produce table DDL like the following: CREATE TABLE dbo.JMS_MESSAGES ( MESSAGEID int NOT NULL, DESTINATION varchar(255) NOT NULL, TXID int NULL, TXOP char(1) NULL, MESSAGEBLOB image NULL ) LOCK DATAROWS WITH EXP_ROW_SIZE=280, MAX_ROWS_PER_PAGE=1 CREATE TABLE dbo.JMS_TRANSACTIONS ( TXID int NULL ) LOCK DATAROWS WITH EXP_ROW_SIZE=4, MAX_ROWS_PER_PAGE=1
Actions
7. Re: Persistence-related exceptions in JMS under heavy load

genman Jan 31, 2005 6:34 PM (in response to ironbeard)

Can you add this to the Wiki?
Actions
8. Re: Persistence-related exceptions in JMS under heavy load

med_soft Jan 31, 2005 9:58 PM (in response to ironbeard)
Not sure where in the Wiki this should go?

As Adrian indicates, (no locking in excess of) row level locking is a requirement no matter what the database. To make that more explicit, the SQL in the /docs/examples/jms/sybase-jdbc2-service.xml should probably be changed to add in the LOCK DATAROWS clauses on the following create statements:

CREATE_MESSAGE_TABLE = CREATE TABLE dbo.JMS_MESSAGES ( MESSAGEID INTEGER NOT NULL, \ DESTINATION VARCHAR(255) NOT NULL, TXID INTEGER NULL, TXOP CHAR(1), \ MESSAGEBLOB IMAGE, PRIMARY KEY (MESSAGEID, DESTINATION) ) LOCK DATAROWS CREATE_TX_TABLE = CREATE TABLE dbo.JMS_TRANSACTIONS ( TXID INTEGER, PRIMARY KEY (TXID) ) \ LOCK DATAROWS
Actions
9. Re: Persistence-related exceptions in JMS under heavy load

starksm64 Feb 1, 2005 1:55 PM (in response to ironbeard)

The original jira issue has been moved to http://jira.jboss.com/jira/browse/JBAS-1368 and the sybase-jdbc2-service.xml DDL statements updated to include the LOCK DATAROWS condition.
Actions

Go to original post