4 Replies Latest reply on Jun 2, 2006 11:49 AM by Manik Surtani

    Query cache lock contention

    Matt Accola Newbie

      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