7 Replies Latest reply on Jan 15, 2010 4:13 PM by Srini c

    JBossCache Deadlock in Hibernate BulkOperationCleanupAction

    Jon McDonald Newbie

      Hi, I'm experiencing a JBossCache deadlock under Hibernate when committing a transaction which performs a Hibernate bulk operation (in this case a single bulk UPDATE statement using Query.executeUpdate()).

      My setup:

      * Spring 2.5.5
      * Hibernate 3.3.1.GA
      * JBossCache 3.0.3.CR1 (also tried 3.0.2.GA)
      * Atomikos Transactions 3.5.2
      * Spring-managed JTA transactions

      I'm using the MVCC locking and READ_COMMITTED isolation level. Clustering is turned off.

      Stack trace beginning from the transaction commit() call:

      2009-02-21 21:53:36,920 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]
      at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:380)
      at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:360)
      at org.hibernate.cache.jbc2.access.TransactionalAccessDelegate.evictOrRemoveAll(TransactionalAccessDelegate.java:146)
      at org.hibernate.cache.jbc2.access.TransactionalAccessDelegate.evictAll(TransactionalAccessDelegate.java:142)
      at org.hibernate.cache.jbc2.entity.TransactionalAccess.evictAll(TransactionalAccess.java:102)
      at org.hibernate.impl.SessionFactoryImpl.evictEntity(SessionFactoryImpl.java:870)
      at org.hibernate.action.BulkOperationCleanupAction.evictEntityRegions(BulkOperationCleanupAction.java:153)
      at org.hibernate.action.BulkOperationCleanupAction.afterTransactionCompletion(BulkOperationCleanupAction.java:132)
      at org.hibernate.engine.ActionQueue.afterTransactionCompletion(ActionQueue.java:198)
      at org.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:451)
      at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:252)
      at org.hibernate.transaction.CacheSynchronization.afterCompletion(CacheSynchronization.java:117)
      at com.atomikos.icatch.jta.Sync2Sync.afterCompletion(Sync2Sync.java:91)
      at com.atomikos.icatch.imp.SynchToFSM.doAfterCompletion(SynchToFSM.java:38)
      at com.atomikos.icatch.imp.SynchToFSM.entered(SynchToFSM.java:59)
      at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:197)
      at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:288)
      at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:481)
      at com.atomikos.icatch.imp.CoordinatorImp.setStateHandler(CoordinatorImp.java:312)
      at com.atomikos.icatch.imp.CoordinatorStateHandler.commit(CoordinatorStateHandler.java:730)
      at com.atomikos.icatch.imp.IndoubtStateHandler.commit(IndoubtStateHandler.java:225)
      at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:807)
      at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1106)
      at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
      at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:297)
      at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:608)
      at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:168)
      at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)
      at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:709)
      at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:678)

      Deadlock occurs intermittently, both under heavy load and no load. About 50% of the time. It remains deadlocked until the JBossCache lock acquisition timeout expires.

      Known issue? Suggestions to fix?

        • 1. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
          Jon McDonald Newbie

          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...

          • 2. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
            Brian Stansberry Master

            Can you post the rest of the logging for this transaction? I want to see why GlobalTransaction::2 is holding a lock on /com/foo/Bar/ENTITY. If all you've done during the tx is a single bulk UPDATE it shouldn't be holding any lock.

            • 3. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
              Jon McDonald Newbie

              Hi Brian,

              Thanks for your help. Note I have also tried the following, without luck:

              - Tried JBossCache 2.1.1 which ships with Hibernate 3.3.1, with the most basic default configuration (MultiplexedJBossCacheRegionFactory and optimistic locking)... lock timeout still occurs. So I don't think this is MVCC-specific.
              - Tried Spring's HibernateTransactionManager instead of JtaTransactionManager, in case it was a synchronization problem involving JtaTransactionManager... lock timeout still occurs.

              I've done my best to extract and annotate the important parts of the log. The sequence here is (1) startup Hibernate / JBossCache (2) perform a single bulk UPDATE statement within a transaction.

              Here is the code for the transaction, using Spring's PlatformTransactionManager interface:

              TransactionStatus status = jtaTransactionManager.getTransaction(new DefaultTransactionDefinition());
              try {
              sessionFactory.getCurrentSession().createQuery("UPDATE MyEntity e SET e.field = 0").executeUpdate();
              } catch (Exception e) {
              jtaTransactionManager.rollback(status);
              throw new RuntimeException(e);
              }
              jtaTransactionManager.commit(status);

              Here is the log (I've inserted headings for the different sections):

              HIBERNATE / JBOSSCACHE STARTUP

              2009-02-26 12:54:46,744 INFO [org.hibernate.transaction.TransactionFactoryFactory] main - <Transaction strategy: com.atomikos.icatch.jta.hibernate3.AtomikosJTATransactionFactory>
              2009-02-26 12:54:46,752 INFO [org.hibernate.transaction.TransactionManagerLookupFactory] main - <instantiating TransactionManagerLookup: com.atomikos.icatch.jta.hibernate3.TransactionManagerLookup>
              2009-02-26 12:54:46,761 INFO [org.hibernate.transaction.TransactionManagerLookupFactory] main - <instantiated TransactionManagerLookup>
              2009-02-26 12:54:46,761 INFO [org.hibernate.cfg.SettingsFactory] main - <Automatic flush during beforeCompletion(): disabled>
              2009-02-26 12:54:46,761 INFO [org.hibernate.cfg.SettingsFactory] main - <Automatic session close at end of transaction: disabled>
              2009-02-26 12:54:46,761 INFO [org.hibernate.cfg.SettingsFactory] main - <JDBC batch size: 15>
              2009-02-26 12:54:46,762 INFO [org.hibernate.cfg.SettingsFactory] main - <JDBC batch updates for versioned data: disabled>
              2009-02-26 12:54:46,762 INFO [org.hibernate.cfg.SettingsFactory] main - <Scrollable result sets: enabled>
              2009-02-26 12:54:46,762 INFO [org.hibernate.cfg.SettingsFactory] main - <JDBC3 getGeneratedKeys(): enabled>
              2009-02-26 12:54:46,762 INFO [org.hibernate.cfg.SettingsFactory] main - <Connection release mode: on_close>
              2009-02-26 12:54:46,763 INFO [org.hibernate.cfg.SettingsFactory] main - <Maximum outer join fetch depth: 2>
              2009-02-26 12:54:46,763 INFO [org.hibernate.cfg.SettingsFactory] main - <Default batch fetch size: 1>
              2009-02-26 12:54:46,764 INFO [org.hibernate.cfg.SettingsFactory] main - <Generate SQL with comments: disabled>
              2009-02-26 12:54:46,764 INFO [org.hibernate.cfg.SettingsFactory] main - <Order SQL updates by primary key: disabled>
              2009-02-26 12:54:46,764 INFO [org.hibernate.cfg.SettingsFactory] main - <Order SQL inserts for batching: disabled>
              2009-02-26 12:54:46,764 INFO [org.hibernate.cfg.SettingsFactory] main - <Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory>
              2009-02-26 12:54:46,767 INFO [org.hibernate.hql.ast.ASTQueryTranslatorFactory] main - <Using ASTQueryTranslatorFactory>
              2009-02-26 12:54:46,767 INFO [org.hibernate.cfg.SettingsFactory] main - <Query language substitutions: {}>
              2009-02-26 12:54:46,767 INFO [org.hibernate.cfg.SettingsFactory] main - <JPA-QL strict compliance: disabled>
              2009-02-26 12:54:46,767 INFO [org.hibernate.cfg.SettingsFactory] main - <Second-level cache: enabled>
              2009-02-26 12:54:46,768 INFO [org.hibernate.cfg.SettingsFactory] main - <Query cache: enabled>
              2009-02-26 12:54:46,768 INFO [org.hibernate.cfg.SettingsFactory] main - <Cache region factory : org.hibernate.cache.jbc2.JBossCacheRegionFactory>
              2009-02-26 12:54:46,771 INFO [org.hibernate.cfg.SettingsFactory] main - <Optimize cache for minimal puts: enabled>
              2009-02-26 12:54:46,771 INFO [org.hibernate.cfg.SettingsFactory] main - <Structured second-level cache entries: disabled>
              2009-02-26 12:54:46,771 INFO [org.hibernate.cfg.SettingsFactory] main - <Query cache factory: org.hibernate.cache.StandardQueryCacheFactory>
              2009-02-26 12:54:46,777 INFO [org.hibernate.cfg.SettingsFactory] main - <Statistics: disabled>
              2009-02-26 12:54:46,777 INFO [org.hibernate.cfg.SettingsFactory] main - <Deleted entity synthetic identifier rollback: disabled>
              2009-02-26 12:54:46,777 INFO [org.hibernate.cfg.SettingsFactory] main - <Default entity-mode: pojo>
              2009-02-26 12:54:46,777 INFO [org.hibernate.cfg.SettingsFactory] main - <Named query checking : enabled>
              2009-02-26 12:54:46,839 INFO [org.hibernate.impl.SessionFactoryImpl] main - <building session factory>
              2009-02-26 12:54:47,765 DEBUG [org.jboss.cache.interceptors.InterceptorChain] main - <Interceptor chain is: InterceptorChain{
              >> org.jboss.cache.interceptors.CallInterceptor
              >> org.jboss.cache.interceptors.MVCCLockingInterceptor
              >> org.jboss.cache.interceptors.NotificationInterceptor
              >> org.jboss.cache.interceptors.TxInterceptor
              >> org.jboss.cache.interceptors.CacheMgmtInterceptor
              >> org.jboss.cache.interceptors.InvocationContextInterceptor
              }>
              2009-02-26 12:54:47,845 INFO [org.jboss.cache.jmx.PlatformMBeanServerRegistration] main - <JBossCache MBeans were successfully registered to the platform mbean server.>
              2009-02-26 12:54:47,847 INFO [org.jboss.cache.factories.ComponentRegistry] main - <JBoss Cache version: JBossCache 'Naga' 3.0.3.GA>

              TRANSACTION (EXECUTES A SINGLE BULK UPDATE QUERY!):

              2009-02-26 12:54:50,032 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Invoked with command RemoveNodeCommand{fqn=/com/foo/MyEntity/ENTITY, dataVersion=null, globalTransaction=GlobalTransaction::1, 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-26 12:54:50,032 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Setting up transactional context.>
              2009-02-26 12:54:50,032 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Setting tx as foo0000100090 and gtx as GlobalTransaction::1>
              2009-02-26 12:54:50,033 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - < local transaction exists - registering global tx if not present for Thread[main,5,main]>
              2009-02-26 12:54:50,033 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Associated gtx in txTable is GlobalTransaction::1>
              2009-02-26 12:54:50,033 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Registering sync handler for tx foo0000100090, gtx GlobalTransaction::1>
              2009-02-26 12:54:50,037 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction::1, tx=com.atomikos.icatch.jta.TransactionImp@2054028))>
              2009-02-26 12:54:50,038 TRACE [org.jboss.cache.lock.MVCCLockManager] main - <Attempting to lock /com/foo/MyEntity/ENTITY>
              2009-02-26 12:54:50,038 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] main - <Nothing to do since there is a transaction in scope.>
              2009-02-26 12:54:50,038 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Resetting invocation-scope options>

              TRANSACTION BEFORE COMPLETION CALLBACK:

              2009-02-26 12:54:50,087 TRACE [org.hibernate.transaction.CacheSynchronization] main - <transaction before completion callback>
              2009-02-26 12:54:50,087 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Running beforeCompletion on gtx GlobalTransaction::1>
              2009-02-26 12:54:50,087 TRACE [org.jboss.cache.interceptors.TxInterceptoreptor] main - <Setting up transactional context.>
              2009-02-26 12:54:50,087 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Setting tx as foo0000100090 and gtx as GlobalTransaction::1>
              2009-02-26 12:54:50,087 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Setting up transactional context.>
              2009-02-26 12:54:50,087 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Setting tx as foo0000100090 and gtx as GlobalTransaction::1>
              2009-02-26 12:54:50,088 TRACE [org.jboss.cache.interceptors.CallInterceptor] main - <Suppressing invocation of method handlePrepareCommand.>
              2009-02-26 12:54:50,088 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] main - <Nothing to do since there is a transaction in scope.>
              2009-02-26 12:54:50,088 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Setting up transactional context.>
              2009-02-26 12:54:50,088 TRACE [org.jboss.cache.interceptors.TxInterceptor] main - <Setting tx as null and gtx as null>

              TRANSACTION AFTER COMPLETION CALLBACK:

              2009-02-26 12:54:50,144 TRACE [org.hibernate.transaction.CacheSynchronization] main - <transaction after completion callback, status: 3>
              2009-02-26 12:54:50,144 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Invoked with command RemoveNodeCommand{fqn=/com/foo/MyEntity/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-26 12:54:50,144 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Setting up transactional context.>
              2009-02-26 12:54:50,144 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Setting tx as null and gtx as null>
              2009-02-26 12:54:50,144 TRACE [org.jboss.cache.lock.MVCCLockManager] main - <Attempting to lock /com/foo/MyEntity/ENTITY>
              2009-02-26 12:55:00,145 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] main - <Nothing to do since there are no modifications in scope.>
              2009-02-26 12:55:00,145 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Resetting invocation-scope options>
              2009-02-26 12:55:00,147 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Invoked with command PutKeyValueCommand{fqn=/TS/org/hibernate/cache/UpdateTimestampsCache/myentities, dataVersion=null, globalTransaction=null, key=item, value=12356709001} 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-26 12:55:00,148 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Setting up transactional context.>
              2009-02-26 12:55:00,150 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Setting tx as null and gtx as null>
              2009-02-26 12:55:00,150 TRACE [org.jboss.cache.lock.MVCCLockManager] main - <Attempting to lock /TS/org/hibernate/cache/UpdateTimestampsCache/myentities>
              2009-02-26 12:55:00,151 TRACE [org.jboss.cache.interceptors.MVCCLockingInterceptor] main - <Releasing lock on [/TS/org/hibernate/cache/UpdateTimestampsCache/myentities] for owner Thread[main,5,main]>
              2009-02-26 12:55:00,151 TRACE [org.jboss.cache.lock.MVCCLockManager] main - <Attempting to unlock /TS/org/hibernate/cache/UpdateTimestampsCache/myentities>
              2009-02-26 12:55:00,151 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Resetting invocation-scope options>
              2009-02-26 12:55:00,153 ERROR [org.hibernate.engine.ActionQueue] main - <could not release a cache lock>
              org.hibernate.cache.CacheException: org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/com/foo/MyEntity/ENTITY] after [10000] milliseconds for requestor [Thread[main,5,main]]! Lock held by [GlobalTransaction::1]
              at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:380)
              at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:360)
              at org.hibernate.cache.jbc2.access.TransactionalAccessDelegate.evictOrRemoveAll(TransactionalAccessDelegate.java:146)
              at org.hibernate.cache.jbc2.access.TransactionalAccessDelegate.evictAll(TransactionalAccessDelegate.java:142)
              at org.hibernate.cache.jbc2.entity.TransactionalAccess.evictAll(TransactionalAccess.java:102)
              at org.hibernate.impl.SessionFactoryImpl.evictEntity(SessionFactoryImpl.java:870)
              at org.hibernate.action.BulkOperationCleanupAction.evictEntityRegions(BulkOperationCleanupAction.java:153)
              at org.hibernate.action.BulkOperationCleanupAction.afterTransactionCompletion(BulkOperationCleanupAction.java:132)
              at org.hibernate.engine.ActionQueue.afterTransactionCompletion(ActionQueue.java:198)
              at org.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:451)
              at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:252)
              at org.hibernate.transaction.CacheSynchronization.afterCompletion(CacheSynchronization.java:117)
              at com.atomikos.icatch.jta.Sync2Sync.afterCompletion(Sync2Sync.java:91)
              at com.atomikos.icatch.imp.SynchToFSM.doAfterCompletion(SynchToFSM.java:38)
              at com.atomikos.icatch.imp.SynchToFSM.entered(SynchToFSM.java:59)
              at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:197)
              at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:288)
              at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:481)
              at com.atomikos.icatch.imp.CoordinatorImp.setStateHandler(CoordinatorImp.java:312)
              at com.atomikos.icatch.imp.CoordinatorStateHandler.commit(CoordinatorStateHandler.java:730)
              at com.atomikos.icatch.imp.IndoubtStateHandler.commit(IndoubtStateHandler.java:225)
              at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:807)
              at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1106)
              at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
              at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:297)
              at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:608)
              at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:168)
              at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)
              at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:709)
              at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:678)
              Caused by: org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/com/foo/MyEntity/ENTITY] after [10000] milliseconds for requestor [Thread[main,5,main]]! Lock held by [GlobalTransaction::1]
              at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:159)
              at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodesRecursivelyForRemoval(MVCCNodeHelper.java:316)
              at org.jboss.cache.interceptors.MVCCLockingInterceptor.handleRemoveNodeCommand(MVCCLockingInterceptor.java:116)
              at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitRemoveNodeCommand(PrePostProcessingCommandInterceptor.java:126)
              at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
              at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
              at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
              at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
              at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.jboss.cache.interceptors.TxInterceptor.attachGtxAndPassUpChain(TxInterceptor.java:261)
              at org.jboss.cache.interceptors.TxInterceptor.handleDefault(TxInterceptor.java:250)
              at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
              at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
              at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
              at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
              at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
              at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
              at org.jboss.cache.interceptors.InvocationContextInterceptor.visitRemoveNodeCommand(InvocationContextInterceptor.java:88)
              at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
              at org.jboss.cache.interceptors.InterceptorChain.invoke(InterceptorChain.java:287)
              at org.jboss.cache.invocation.CacheInvocationDelegate.removeNode(CacheInvocationDelegate.java:409)
              at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:378)
              ... 136 more

              Cheers,
              Jon

              • 4. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
                Brian Stansberry Master

                Is there anything from Hibernate before the first bit in the "TRANSACTION (EXECUTES A SINGLE BULK UPDATE QUERY!)":

                2009-02-26 12:54:50,032 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] main - <Invoked with command RemoveNodeCommand{fqn=/com/foo/MyEntity/ENTITY....


                I want to understand why that call is being triggered by your query.

                • 5. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
                  nandan jain Newbie

                  Hi All,
                  I m using Jboss 5.1.0 in clustered environment. Hibernate version is 3.3.1.
                  whenever i try to delete multiple lines from the db, after the operation i get an exception like below.


                  16:45:10,621 ERROR [ActionQueue] could not release a cache lock
                  org.hibernate.cache.CacheException: java.lang.IllegalStateException: Transaction TransactionImple < ac, BasicAction: 7f000001:e946:4b1e3199:71 status: ActionStatus.COMMITTED > is not in a valid state to be invoking cache operations on.
                   at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:380)
                   at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:360)
                   at org.hibernate.cache.jbc2.access.TransactionalAccessDelegate.evictOrRemoveAll(TransactionalAccessDelegate.java:146)
                   at org.hibernate.cache.jbc2.access.TransactionalAccessDelegate.evictAll(TransactionalAccessDelegate.java:142)
                   at org.hibernate.cache.jbc2.entity.TransactionalAccess.evictAll(TransactionalAccess.java:102)
                   at org.hibernate.impl.SessionFactoryImpl.evictEntity(SessionFactoryImpl.java:870)
                   at org.hibernate.action.BulkOperationCleanupAction.evictEntityRegions(BulkOperationCleanupAction.java:153)
                   at org.hibernate.action.BulkOperationCleanupAction.afterTransactionCompletion(BulkOperationCleanupAction.java:132)
                   at org.hibernate.engine.ActionQueue.afterTransactionCompletion(ActionQueue.java:198)
                   at org.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:451)
                   at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:252)
                   at org.hibernate.transaction.CacheSynchronization.afterCompletion(CacheSynchronization.java:117)
                   at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:123)
                   at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:381)
                   at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99)
                   at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
                   at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)
                   at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)
                   at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
                   at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:170)
                   at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87)
                   at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:190)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.aspects.remoting.ReplicantsManagerInterceptor.invoke(ReplicantsManagerInterceptor.java:52)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptorv2.invoke(RoleBasedAuthorizationInterceptorv2.java:201)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:186)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:41)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
                   at org.jboss.ejb3.session.SessionSpecContainer.invoke(SessionSpecContainer.java:176)
                   at org.jboss.ejb3.session.SessionSpecContainer.invoke(SessionSpecContainer.java:216)
                   at org.jboss.ejb3.proxy.impl.handler.session.SessionProxyInvocationHandlerBase.invoke(SessionProxyInvocationHandlerBase.java:207)
                   at org.jboss.ejb3.proxy.impl.handler.session.SessionProxyInvocationHandlerBase.invoke(SessionProxyInvocationHandlerBase.java:164)
                   at $Proxy476.scheduledBackTrack(Unknown Source)
                   at com.dxd.server.notification.BackTrackSchedular$1.run(BackTrackSchedular.java:87)
                   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
                   at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
                   at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
                   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
                   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:181)
                   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:205)
                   at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                   at java.lang.Thread.run(Thread.java:619)
                  Caused by: java.lang.IllegalStateException: Transaction TransactionImple < ac, BasicAction: 7f000001:e946:4b1e3199:71 status: ActionStatus.COMMITTED > is not in a valid state to be invoking cache operations on.
                   at org.jboss.cache.interceptors.TxInterceptor.registerTransaction(TxInterceptor.java:727)
                   at org.jboss.cache.interceptors.TxInterceptor.attachGlobalTransaction(TxInterceptor.java:474)
                   at org.jboss.cache.interceptors.TxInterceptor.attachGtxAndPassUpChain(TxInterceptor.java:300)
                   at org.jboss.cache.interceptors.TxInterceptor.handleDefault(TxInterceptor.java:283)
                   at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
                   at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
                   at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
                   at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
                   at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
                   at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
                   at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
                   at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
                   at org.jboss.cache.interceptors.InvocationContextInterceptor.visitRemoveNodeCommand(InvocationContextInterceptor.java:88)
                   at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
                   at org.jboss.cache.interceptors.InterceptorChain.invoke(InterceptorChain.java:287)
                   at org.jboss.cache.invocation.CacheInvocationDelegate.removeNode(CacheInvocationDelegate.java:478)
                   at org.jboss.ha.cachemanager.CacheManagerManagedCache.removeNode(CacheManagerManagedCache.java:317)
                   at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:378)
                   ... 53 more


                  Can somebody help me regarding this issue.
                  I came to know that this is a bug in hibernate when doing a evitAll(). But now what should i do to resolve it.

                  Thanks in advance....

                  • 6. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAct
                    Galder Zamarreño Master

                    First of all, please avoid hijacking other people's thread

                     

                    Secondly, as you already know, there's an issue with Hibernate 3.3.1 and evictAll calls when using JBC as 2LC (HHH-3818). Workarounds? Either, get the latest Hibernate 3.3.x branch code, build it and use that, or use JBoss 6.0.0.M1 that uses Hibernate 3.5.beta2 that includes a fix for that issue.

                    • 7. Re: JBossCache Deadlock in Hibernate BulkOperationCleanupAction
                      Srini c Newbie

                      I have very similar issue as mentioned in this original issue. I am waiting for help towards the resolution.

                       

                      http://community.jboss.org/message/271296#271296