[jboss-user] [JBoss Cache: Core Edition] - Lost locks after exception during rollback
kblanken
do-not-reply at jboss.com
Wed Oct 22 06:57:05 EDT 2008
We're running JBC 1.4.1SP9 under WebSphere Application Server 6.0. In our application, we're processing multiple file imports in parallel threads.
In this scenario we observe lost cache locks. In other words, the lock table contains locks from transactions that have been rolled back or commited. These locks block later transactions from modifying the nodes.
We've been able to reproduce this to some extent, here's what we know.
The following is a part of our logfile that I stripped down a bit. org.jboss.cache.interceptors.TxInterceptor is configured to trace. The transaction that interfers later is no. 199, so this is what it does:
| 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_put; id:1; Args: ( arg[0] = GlobalTransaction:<null>:199 ...)];;;;;FINEST;;
| 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344, gtx GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:21 ;org.jboss.cache.interceptors.TxInterceptor;;;registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:199, tx=com.ibm.ws.Transaction.JTA.TransactionImpl at 283072741));;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)])];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)])];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)])];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:201 ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:201;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344, gtx GlobalTransaction:<null>:201;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:201, tx=com.ibm.ws.Transaction.JTA.TransactionImpl at 283072741));;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:199 ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:201 ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:201;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:199 ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:201 ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:201;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:199 already owns lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/MIN_FTC/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,MIN_FTC,2008-05-29,2008-05-29)] ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/MAX_FTC/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,MAX_FTC,2008-05-29,2008-05-29)] ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/200000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,200000,DUE_OUTPUT,2008-05-29,2008-05-29)] ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:26; Args: ( arg[0] = /values/BASELOAD/DUE_OUTPUT/200000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,200000,DUE_OUTPUT,2008-05-29,2008-05-29)] ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is null;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 0,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl at 39ff58df#tid=1349, gtx GlobalTransaction:<null>:202;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 10df58e5#tid=1344 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:202, tx=com.ibm.ws.Transaction.JTA.TransactionImpl at 973035743));;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_put; id:1; Args: ( arg[0] = GlobalTransaction:<null>:202 ...)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:202;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 39ff58df#tid=1349 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;upgrading RL to WL for GlobalTransaction:<null>:202, timeout=15000, locks: Read lock owners: [GlobalTransaction:<null>:199, GlobalTransaction:<null>:202]
| Write lock owner: null
| ;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.lock.IdentityLock;;;upgrading lock for /values/BASELOAD/DUE_OUTPUT/200000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,200000,DUE_OUTPUT,2008-05-29,2008-05-29)];;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;calling aftercompletion for GlobalTransaction:<null>:199;;;;;FINEST;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;;Running rollback phase;;;;;FINE;;
| 2008-10-07 19:34:22 ;org.jboss.cache.interceptors.TxInterceptor;;; running rollback for GlobalTransaction:<null>:199;;;;;FINEST;;
|
Obviously, #199 had a problem somewhere and is being rolled back. Nothing unusual so far, and I'd expect the rollback to continue with a "Finished local commit/rollback method" message. But there's nothing like that at this point of the log file.
Instead, this is the next time transaction #199 occurs in the log (15 seconds later):
| 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_get; id:31; Args: ( arg[0] = /values/BASELOAD/MIN_FTC/313020100/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020100,MIN_FTC,2008-05-29,2008-05-29)])];;;;;FINEST;;
| 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;;
| 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:214;;;;;FINEST;;
| 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;Transaction com.ibm.ws.Transaction.JTA.TransactionImpl at 13a698dc#tid=1492 is already registered.;;;;;FINE;;
| 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;Identity;1;other ; ;;org.jboss.cache.lock.IdentityLock;;;acquireReadLock(): caller GlobalTransaction:<null>:214 already owns lock for /values/BASELOAD/MIN_FTC/313020100/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020100,MIN_FTC,2008-05-29,2008-05-29)];;;;;FINEST;;
| 2008-10-07 19:34:37 ;GMT+01:00 ;S83XB ;Identity;1;other ; ;;org.jboss.cache.lock.IdentityLock;;;read lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] could not be acquired by Thread[WebContainer : 0,5,main] after 15000 ms. Locks: Read lock owners: []
| Write lock owner: GlobalTransaction:<null>:199
| , lock info: write owner=GlobalTransaction:<null>:199 (org.jboss.cache.lock.LockStrategyReadCommitted at 369798d2);;;;;FINEST;;
|
This is the next time transaction #199 occurs (again, 15 seconds later):
| 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;(null) call on method [_remove; id:5; Args: ( arg[0] = GlobalTransaction:<null>:224 ...)];;;;;FINEST;;
| 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;; local transaction exists - registering global tx if not present for Thread[WebContainer : 1,5,main];;;;;FINE;;
| 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;TxInterc;1;other ; ;;org.jboss.cache.interceptors.TxInterceptor;;;Associated gtx in txTable is GlobalTransaction:<null>:224;;;;;FINEST;;
| 2008-10-07 19:34:52 ;GMT+01:00 ;S83XB ;Identity;1;other ; ;;org.jboss.cache.lock.IdentityLock;;;read lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] could not be acquired by Thread[WebContainer : 0,5,main] after 15000 ms. Locks: Read lock owners: []
| Write lock owner: GlobalTransaction:<null>:199
| , lock info: write owner=GlobalTransaction:<null>:199 (org.jboss.cache.lock.LockStrategyReadCommitted at 369798d2);;;;;FINEST;;
|
These are the only two times a lock could not be obtained, and both times transaction #199 blocks them.
The following is the first time "Finished rollback phase" is logged after "Running rollback phase". Between there and here it's 45 seconds of time or 75,000 lines of log file. Note that the expected "Finished local commit/rollback method for GlobalTransaction::199" is never logged! I conclude from this that it's transaction #199 that has a problem with its rollback phase:
| 2008-10-07 19:35:07 ;org.jboss.cache.lock.IdentityLock;;;read lock for /values/BASELOAD/DUE_OUTPUT/260700000/[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] could not be acquired by Thread[WebContainer : 0,5,main] after 15000 ms. Locks: Read lock owners: []
| Write lock owner: GlobalTransaction:<null>:199
| , lock info: write owner=GlobalTransaction:<null>:199 (org.jboss.cache.lock.LockStrategyReadCommitted at 369798d2);;;;;FINEST;;
| 2008-10-07 19:35:07 ;org.jboss.cache.interceptors.TxInterceptor;;;Rollback had a problem;;;;;WARNING;;
| 2008-10-07 19:35:07 ;org.jboss.cache.interceptors.TxInterceptor;;;Finished rollback phase;;;;;FINE;;
| 2008-10-07 19:35:07 ;com.sdm.p69.fileadapter.internal.importer.TransportObjectProcessor;;UNCAUGHT; Stack Trace:
| javax.ejb.TransactionRolledbackLocalException: ; nested exception is: java.util.ConcurrentModificationException
| java.util.ConcurrentModificationException
| at java.util.AbstractList$Itr.checkForComodification(AbstractList.java(Inlined Compiled Code))
| at java.util.AbstractList$Itr.next(AbstractList.java(Compiled Code))
| at com.sdm.p32.clustertargetvalue.internal.ServiceTargetValueSet_NewCache.containsTargetValueData(ServiceTargetValueSet_NewCache.java(Compiled Code))
|
Of course we can fix the ConcurrentModificationException in our code, but such an error must not lead to lost locks.
Much later in the log, the lock by transaction #199 still persists and blocks any other locking attempts. Additionally, further locks seem to stack (tx #574):
| 2008-10-07 19:38:50 ;com.sdm.p69.fileadapter.internal.importer.TransportObjectProcessor;;UNCAUGHT; Stack Trace:
| javax.ejb.TransactionRolledbackLocalException: ; nested exception is: Cache "TargetValueCacheDistributed": failure acquiring lock: fqn=/values/BASELOAD/DUE_OUTPUT/260201020,
| caller=GlobalTransaction:<null>:592, lock=write owner=GlobalTransaction:<null>:574 (org.jboss.cache.lock.LockStrategyReadCommitted at 2baa18c4)
| TargetValueCacheDistributed lock information follows:
| Own transaction: GlobalTransaction:<null>:592
| Locking scheme: PESSIMISTIC, READ_COMMITTED
|
| Root lock: (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593])
| /values (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593])
| /BASELOAD (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593])
| /DUE_OUTPUT (read owners=[GlobalTransaction:<null>:199, GlobalTransaction:<null>:592, GlobalTransaction:<null>:593])
| /491000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,491000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /550000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,550000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /300004100 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,300004100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /90000014 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,90000014,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /313060100 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313060100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /540000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,540000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /262104000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,262104000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /303250 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,303250,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /530000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,530000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /360005405 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,360005405,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /260201010 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260201010,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /360002200 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,360002200,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /260102000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260102000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /520000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,520000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /312040000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,312040000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /510000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,510000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /313020100 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /312020000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,312020000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /260201020 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260201020,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /307990799 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,307990799,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /311100000 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,311100000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /300520 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,300520,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /410010100 (write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,410010100,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:574)
| /260700000 (read owners=[GlobalTransaction:<null>:199], write owner=GlobalTransaction:<null>:574)
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,260700000,DUE_OUTPUT,2008-05-29,2008-05-29)] (write owner=GlobalTransaction:<null>:199)
| /300006000
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,300006000,DUE_OUTPUT,2008-05-29,2008-05-29)]
| /112000
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,112000,DUE_OUTPUT,2008-05-29,2008-05-29)]
| /311040000
|
|
|
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,311040000,DUE_OUTPUT,2008-05-29,2008-05-29)]
| /313020210
| /[com.sdm.p32.clustertargetvalue.internal.cache.targetvalue.FindMatchingTargetValue(BASELOAD,313020210,DUE_OUTPUT,2008-05-29,2008-05-29)]
|
Are these conclusions correct? Even if they're not, IMO this kind of situation shouldn't leave these locks in the lock table.
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4183799#4183799
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4183799
More information about the jboss-user
mailing list