Query cache lock contention
I am using optimistic locking with JBoss Cache 1.3.0.SP2 and Hibernate 3.2.CR2. I have a very short-running block of authentication code which runs a couple of queries within a transaction and then updates a single row in the database (all using hibernate). Since this block gets executed very frequently there is a high level of concurrency. What appears to be happening is that during cache invalidation on the UpdateTimestampsCache, two separate JTA transactions get into a state of contention and neither is allowed to continue until one times out. Then the timed out transaction rolls back and the other transaction releases the lock and continues on. Please see the below log4j output. Transaction 1423 and 1424 are the transactions with contention.
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:162) 2006-05-23 18:04:16,624 - Bound value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.aop.interceptor.SimpleTraceInterceptor:56) 2006-05-23 18:04:16,624 - Entering invocation: method 'supports', arguments [class fleetcycle.services.framework.security.acegisecurity.CredentialsAuthenticationToken]; target is of class [fleetcycle.services.framework.security.acegisecurity.FeatureBasedAuthenticationProvider]; count=15
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.aop.interceptor.SimpleTraceInterceptor:59) 2006-05-23 18:04:16,624 - Exiting invocation: method 'supports', arguments [class fleetcycle.services.framework.security.acegisecurity.CredentialsAuthenticationToken]; target is of class [fleetcycle.services.framework.security.acegisecurity.FeatureBasedAuthenticationProvider]; count=15
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.aop.interceptor.SimpleTraceInterceptor:56) 2006-05-23 18:04:16,624 - Entering invocation: method 'authenticate', arguments [fleetcycle.services.framework.security.acegisecurity.CredentialsAuthenticationToken@74f14c8a: Username: 8a8a82170b637a44010b637cd41c0001; Password: [PROTECTED]; Authenticated: false; Details: null; Not granted any authorities]; target is of class [fleetcycle.services.framework.security.acegisecurity.FeatureBasedAuthenticationProvider]; count=16
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.interceptor.TransactionAspectSupport:221) 2006-05-23 18:04:16,624 - Getting transaction for net.sf.acegisecurity.providers.AuthenticationProvider.authenticate
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.AbstractPlatformTransactionManager:253) 2006-05-23 18:04:16,624 - Using transaction object [org.springframework.transaction.jta.JtaTransactionObject@2bb9cc8a]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.AbstractPlatformTransactionManager:280) 2006-05-23 18:04:16,624 - Creating new transaction with name [net.sf.acegisecurity.providers.AuthenticationProvider.authenticate]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:214) 2006-05-23 18:04:16,624 - Initializing transaction synchronization
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,624 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,639 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,639 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,639 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,639 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,639 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.hibernate.cache.UpdateTimestampsCache:51) 2006-05-23 18:04:16,639 - Pre-invalidating space [USER_SESSION]
DEBUG [Servlet.Engine.Transports : 1] (org.springframework.transaction.support.AbstractPlatformTransactionManager:493) 2006-05-23 18:04:16,655 - Initiating transaction commit
DEBUG [Servlet.Engine.Transports : 1] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:67) 2006-05-23 18:04:16,655 - Calling lockNodes() with gtx GlobalTransaction::1423
DEBUG [Servlet.Engine.Transports : 1] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:132) 2006-05-23 18:04:16,655 - locking nodes
DEBUG [Servlet.Engine.Transports : 1] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:144) 2006-05-23 18:04:16,655 - acquired lock on node USER_SESSION
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,655 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.hibernate.cache.UpdateTimestampsCache:64) 2006-05-23 18:04:16,655 - Invalidating space [USER_SESSION], timestamp: 11484254566
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,671 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,671 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,671 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,671 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,671 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.TransactionSynchronizationManager:137) 2006-05-23 18:04:16,671 - Retrieved value [org.springframework.orm.hibernate3.SessionHolder@6d580c8a] for key [org.hibernate.impl.SessionFactoryImpl@6e290cfe] bound to thread [Servlet.Engine.Transports : 2]
DEBUG [Servlet.Engine.Transports : 2] (org.hibernate.cache.UpdateTimestampsCache:51) 2006-05-23 18:04:16,686 - Pre-invalidating space [USER_SESSION]
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.interceptor.TransactionAspectSupport:264) 2006-05-23 18:04:16,686 - Invoking commit for transaction on net.sf.acegisecurity.providers.AuthenticationProvider.authenticate
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.AbstractPlatformTransactionManager:653) 2006-05-23 18:04:16,686 - Triggering beforeCommit synchronization
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.AbstractPlatformTransactionManager:669) 2006-05-23 18:04:16,686 - Triggering beforeCompletion synchronization
DEBUG [Servlet.Engine.Transports : 2] (org.springframework.transaction.support.AbstractPlatformTransactionManager:493) 2006-05-23 18:04:16,702 - Initiating transaction commit
DEBUG [Servlet.Engine.Transports : 2] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:67) 2006-05-23 18:04:16,702 - Calling lockNodes() with gtx GlobalTransaction::1424
DEBUG [Servlet.Engine.Transports : 2] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:132) 2006-05-23 18:04:16,702 - locking nodes
DEBUG [Servlet.Engine.Transports : 2] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:72) 2006-05-23 18:04:16,702 - Caught exception attempting to lock nodes
java.lang.IllegalStateException: there is already a writer holding the lock: GlobalTransaction::1423
at org.jboss.cache.lock.LockMap.setWriterIfNotNull(LockMap.java:100)
at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:187)
at org.jboss.cache.Node.acquireWriteLock(Node.java:557)
at org.jboss.cache.Node.acquire(Node.java:517)
at org.jboss.cache.interceptors.OptimisticLockingInterceptor.lockNodes(OptimisticLockingInterceptor.java:141)
at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:68)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:67)
at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:781)
at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1043)
at org.jboss.cache.interceptors.OrderedSynchronizationHandler.beforeCompletion(OrderedSynchronizationHandler.java:72)
at com.ibm.ws.Transaction.JTA.RegisteredSyncs.distributeBefore(RegisteredSyncs.java:136)
at com.ibm.ws.Transaction.JTA.TransactionImpl.internalPrepare(TransactionImpl.java:1234)
at com.ibm.ws.Transaction.JTA.TransactionImpl.commit(TransactionImpl.java:983)
at com.ibm.ws.Transaction.JTA.TranManagerImpl.commit(TranManagerImpl.java:150)
at com.ibm.ws.Transaction.JTA.TranManagerSet.commit(TranManagerSet.java:177)
at com.ibm.ws.Transaction.JTA.UserTransactionImpl.commit(UserTransactionImpl.java:262)
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:781)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:496)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:469)
at org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:266)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.aop.interceptor.SimpleTraceInterceptor.invokeUnderTrace(SimpleTraceInterceptor.java:58)
at org.springframework.aop.interceptor.AbstractTraceInterceptor.invoke(AbstractTraceInterceptor.java:94)
at org.springframework.aop.interceptor.DebugInterceptor.invoke(DebugInterceptor.java:57)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:176)
at $Proxy7.authenticate(Unknown Source)
at net.sf.acegisecurity.providers.ProviderManager.doAuthentication(ProviderManager.java:128)
at net.sf.acegisecurity.AbstractAuthenticationManager.authenticate(AbstractAuthenticationManager.java:49)
at fleetcycle.ui.framework.security.AbstractAuthenticationFilter.attemptAuthentication(AbstractAuthenticationFilter.java:186)
at fleetcycle.ui.framework.security.AbstractAuthenticationFilter.doFilter(AbstractAuthenticationFilter.java:114)
at net.sf.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:105)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:132)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:71)
at fleetcycle.ui.framework.actions.SessionFilter.doFilterInternal(SessionFilter.java:76)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at net.sf.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:105)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:132)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:71)
at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:174)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:132)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:71)
at com.ibm.ws.webcontainer.webapp.WebAppRequestDispatcher.handleWebAppDispatch(WebAppRequestDispatcher.java:1162)
at com.ibm.ws.webcontainer.webapp.WebAppRequestDispatcher.dispatch(WebAppRequestDispatcher.java:676)
at com.ibm.ws.webcontainer.webapp.WebAppRequestDispatcher.forward(WebAppRequestDispatcher.java:203)
at com.ibm.ws.webcontainer.srt.WebAppInvoker.doForward(WebAppInvoker.java:125)
at com.ibm.ws.webcontainer.srt.WebAppInvoker.handleInvocationHook(WebAppInvoker.java:300)
at com.ibm.ws.webcontainer.cache.invocation.CachedInvocation.handleInvocation(CachedInvocation.java:71)
at com.ibm.ws.webcontainer.srp.ServletRequestProcessor.dispatchByURI(ServletRequestProcessor.java:246)
at com.ibm.ws.webcontainer.oselistener.OSEListenerDispatcher.service(OSEListener.java:334)
at com.ibm.ws.webcontainer.http.HttpConnection.handleRequest(HttpConnection.java:56)
at com.ibm.ws.http.HttpConnection.readAndHandleRequest(HttpConnection.java:652)
at com.ibm.ws.http.HttpConnection.run(HttpConnection.java:448)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:936)
DEBUG [Servlet.Engine.Transports : 1] (org.jboss.cache.interceptors.OptimisticLockingInterceptor:166) 2006-05-23 18:04:16,749 - releasing lock write owner=GlobalTransaction::1423
