5 Replies Latest reply on Aug 13, 2010 12:09 PM by jnadler

    Infinispan as Hibernate 2LC and Lock TimeoutExceptions

    jnadler

      We have moved our app from Ehcache to Infinispan for Hibernate second level cache.   I am testing Infinispan standalone in an attempt to get an "apples to apples" comparison (no distribution/clustering) with Ehcache.

       

      We're having major locking problems.  It must be something in my configuration (or worse yet, my code!), because no one else seems to be having this kind of issue.  To be clear I'm not asserting any problem in Infinispan.  Everything worked fine in Ehcache with a 60s lock timeout, but we are running the same 60s lock timeout in Infinispan and we see Lock TimeoutExceptions all the time now.

       

      Performance testing of the app confirms that something different is happening - Infinispan cache locks appear to be blocking much more than Ehcache locks were, and the scalability of our software has plummeted as a result.   Combine that with the frequent failures due to timeout and the app is not running well at all.

       

      All of my entities are cache annotated like this:  @Cache(usage=CacheConcurrencyStrategy.TRANSACTIONAL, region="party")

       

      I'm a bit stuck - can anyone suggest how I might debug locking problems like this one below:

       

       

       

      org.hibernate.cache.CacheException: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [60 seconds] on key [com.attensa.core.entity.Ontology#97] for requestor [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-3,1,main], coinToss=7820189512452189956} GlobalTransaction:<null>:300]! Lock held by [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-4,1,main], coinToss=3775955681055831416} GlobalTransaction:<null>:285]
      javax.persistence.PersistenceException: org.hibernate.cache.CacheException: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [60 seconds] on key [com.attensa.core.entity.Ontology#97] for requestor [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-3,1,main], coinToss=7820189512452189956} GlobalTransaction:<null>:300]! Lock held by [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-4,1,main], coinToss=3775955681055831416} GlobalTransaction:<null>:285]
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1235)
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1168)
          at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1174)
          at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:794)
          at sun.reflect.GeneratedMethodAccessor164.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
          at $Proxy118.flush(Unknown Source)
          at sun.reflect.GeneratedMethodAccessor164.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
          at $Proxy118.flush(Unknown Source)
          at com.attensa.core.persistence.dao.GenericDAOHibernateImpl.create(GenericDAOHibernateImpl.java:96)
          at com.attensa.core.persistence.dao.GenericDAOHibernateImpl.create(GenericDAOHibernateImpl.java:83)
          at com.attensa.core.controller.GenericControllerImpl.create(GenericControllerImpl.java:37)
          at sun.reflect.GeneratedMethodAccessor173.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
          at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
          at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
          at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
          at $Proxy128.create(Unknown Source)
          at com.attensa.core.services.postaggregation.PersistArticles.persistArticles(PersistArticles.java:79)
          at com.attensa.core.services.postaggregation.PersistArticles.execute(PersistArticles.java:39)
          at com.attensa.core.services.postaggregation.AbstractPostAggregationCommand.execute(AbstractPostAggregationCommand.java:15)
          at sun.reflect.GeneratedMethodAccessor67.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
          at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
          at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
          at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
          at $Proxy123.execute(Unknown Source)
          at org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:191)
          at com.attensa.core.services.AggregationServiceImpl.processEvent(AggregationServiceImpl.java:209)
          at com.attensa.core.services.AggregationServiceImpl.processEvent(AggregationServiceImpl.java:1)
          at sun.reflect.GeneratedMethodAccessor190.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
          at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
          at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
          at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
          at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
          at $Proxy142.processEvent(Unknown Source)
          at com.attensa.core.job.AggregationJobImpl.executeInternal(AggregationJobImpl.java:72)
          at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
          at org.quartz.core.JobRunShell.run(JobRunShell.java:214)
          at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
      Caused by: org.hibernate.cache.CacheException: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [60 seconds] on key [com.attensa.core.entity.Ontology#97] for requestor [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-3,1,main], coinToss=7820189512452189956} GlobalTransaction:<null>:300]! Lock held by [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-4,1,main], coinToss=3775955681055831416} GlobalTransaction:<null>:285]
          at org.hibernate.cache.infinispan.util.CacheAdapterImpl.put(CacheAdapterImpl.java:98)
          at org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.update(TransactionalAccessDelegate.java:128)
          at org.hibernate.cache.infinispan.entity.TransactionalAccess.update(TransactionalAccess.java:64)
          at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:171)
          at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:268)
          at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:260)
          at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:180)
          at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
          at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51)
          at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1206)
          at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:791)
          ... 59 more
      Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [60 seconds] on key [com.attensa.core.entity.Ontology#97] for requestor [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-3,1,main], coinToss=7820189512452189956} GlobalTransaction:<null>:300]! Lock held by [DeadlockDetectingGlobalTransaction{replicatingTo=[], replicationThread=Thread[schedulerFactoryBean_Worker-4,1,main], coinToss=3775955681055831416} GlobalTransaction:<null>:285]
          at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:213)
          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:148)
          at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
          at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:197)
          at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
          at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
          at org.infinispan.interceptors.DeadlockDetectingInterceptor.handleDataCommand(DeadlockDetectingInterceptor.java:70)
          at org.infinispan.interceptors.DeadlockDetectingInterceptor.visitPutKeyValueCommand(DeadlockDetectingInterceptor.java:102)
          at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
          at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
          at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
          at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
          at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
          at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
          at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:183)
          at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:132)
          at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
          at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
          at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:113)
          at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
          at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
          at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:58)
          at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:39)
          at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
          at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
          at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:271)
          at org.infinispan.CacheDelegate.put(CacheDelegate.java:426)
          at org.infinispan.CacheSupport.put(CacheSupport.java:28)
          at org.hibernate.cache.infinispan.util.CacheAdapterImpl.put(CacheAdapterImpl.java:96)
          ... 69 more

        • 1. Re: Infinispan as Hibernate 2LC and Lock TimeoutExceptions
          jnadler

          A bit more information:

           

          In the stack trace above, the code is executing a JPA EntityManager.create(Article); even though the code is only trying to create an Article it's trying to get an exclusive lock on an instance of a different persistent class, Ontology.

           

          I'm not sure why this would happen, is there anyone more familiar with the Hibernate -> Cache interaction that can enlighten me?  Why would it lock an instance of entity B while creating an instance of entity A?

           

          Also Article is annotated with: @Cache(usage = CacheConcurrencyStrategy.NONE) which I intend to mean "do not cache any instances of this entity in the L2 cache".    Given that annotation, when I create an Article I would expect no cache locks to be acquired.   Is something wrong with my assumption?

          • 2. Re: Infinispan as Hibernate 2LC and Lock TimeoutExceptions
            manik

            One of the things you could look at is increasing the "concurrencyLevel" attribute in the "locking" element.  Or maybe even disable "lockStriping", if you have a very large number of concurrent threads.

            • 3. Re: Infinispan as Hibernate 2LC and Lock TimeoutExceptions
              jnadler

              Thanks Manik.  I've come to the conclusion that the problem is in our code.  It is still unclear why I didn't see the same issue with EHCache.   In theory isolation is read committed in both cases.  We are currently working on a fix and will retest.

              • 4. Re: Infinispan as Hibernate 2LC and Lock TimeoutExceptions
                galder.zamarreno

                It appears that creating an Article somehow updates an existing Ontology entity. What's the relationship between them two entity types?

                 

                Can you attach the hibernate.cfg.xml or persistence.xml that you're using? If you're defining your own Infinispan configuration via hibernate.cache.infinispan.cfg or cache.infinispan.cfg property, attach that file as well. I suppose you are indeed using your own configuration because you're saying that you have modified lock timeout to be 60 seconds.

                • 5. Re: Infinispan as Hibernate 2LC and Lock TimeoutExceptions
                  jnadler

                  Thanks for the reply Galder.  You're absolutely correct - adding an article was causing a Hibernate Auto-Flush.  That's what was trying to persist an Ontology causing the cache lock.

                   

                  I've pinned down a couple of problems in our code (plus some problems in the Atomikos transaction manager) that caused this process to exceed 60s in some cases.  So it had nothing to do with Infinispan and the only open question in my mind is "why didn't I see the same problem with EHCache".  Maybe EHCache doesn't properly enforce lock timeouts.