[JBoss Cache: Core Edition] - Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
by jonmc
Hi, please could anyone give me a hint with this? I've tried seemingly every combination of configuration, and can't get past this lock timeout.
After committing a transaction containing a single UPDATE statement, Hibernate's CacheSynchronization.afterCompletion tries to evict the entire entity region. This goes through JBossCache's removeAll, where the lock timeout occurs.
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/com/foo/Bar/ENTITY] after [10000] milliseconds for requestor [Thread[main,5,main]]! Lock held by [GlobalTransaction::2]
Here is the Hibernate/JBossCache trace leading up to the lock timeout. It shows Hibernate's CacheSynchronization beforeCompletion callback and afterCompletion callback. You can see that the transaction is null in afterCompletion (makes sense since it's completed at that point), yet Hibernate is writing to JBossCache anyway. It seems to update the timestamps cache successfully before deadlocking on the entity region eviction:
09-02-25 22:41:10,888 TRACE [org.hibernate.transaction.CacheSynchronization] - <transaction before completion callback>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Running beforeCompletion on gtx GlobalTransaction::2>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Setting up transactional context.>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Setting tx as tx0000200056 and gtx as GlobalTransaction::2>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Setting up transactional context.>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Setting tx as tx0000200056 and gtx as GlobalTransaction::2>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.CallInterceptor] - <Suppressing invocation of method handlePrepareCommand.>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] - <Nothing to do since there is a transaction in scope.>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Setting up transactional context.>
2009-02-25 22:41:10,889 TRACE [org.jboss.cache.interceptors.TxInterceptor] - <Setting tx as null and gtx as null>
2009-02-25 22:41:10,904 TRACE [org.hibernate.transaction.CacheSynchronization] - <transaction after completion callback, status: 3>
2009-02-25 22:41:10,905 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Invoked with command RemoveNodeCommand{fqn=/com/foo/Bar/ENTITY, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=true}]>
2009-02-25 22:41:10,905 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Setting up transactional context.>
2009-02-25 22:41:10,905 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Setting tx as null and gtx as null>
2009-02-25 22:41:10,905 TRACE [org.jboss.cache.lock.MVCCLockManager] - <Attempting to lock /com/foo/Bar/ENTITY>
2009-02-25 22:41:20,906 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] - <Nothing to do since there are no modifications in scope.>
2009-02-25 22:41:20,907 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Resetting invocation-scope options>
2009-02-25 22:41:20,907 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Invoked with command PutKeyValueCommand{fqn=/TS/org/hibernate/cache/UpdateTimestampsCache/bars, dataVersion=null, globalTransaction=null, key=item, value=12356196809} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=true, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=true}]>
2009-02-25 22:41:20,907 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Setting up transactional context.>
2009-02-25 22:41:20,907 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Setting tx as null and gtx as null>
2009-02-25 22:41:20,907 TRACE [org.jboss.cache.lock.MVCCLockManager] - <Attempting to lock /TS/org/hibernate/cache/UpdateTimestampsCache/bars>
2009-02-25 22:41:20,908 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] - <Releasing lock on [/TS/org/hibernate/cache/UpdateTimestampsCache/bars] for owner Thread[main,5,main]>
2009-02-25 22:41:20,908 TRACE [org.jboss.cache.lock.MVCCLockManager] - <Attempting to unlock /TS/org/hibernate/cache/UpdateTimestampsCache/bars>
2009-02-25 22:41:20,908 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] - <Resetting invocation-scope options>
2009-02-25 22:41:20,910 ERROR [org.hibernate.engine.ActionQueue] - <could not release a cache lock>
org.hibernate.cache.CacheException: org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/com/foo/Bar/ENTITY] after [10000] milliseconds for requestor [Thread[main,5,main]]! Lock held by [GlobalTransaction::2]
Any help is greatly appreciated. I can dig in more if I just know where to look...
View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4213233#4213233
Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4213233
17 years, 1 month