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
