Infinispan as Hibernate 2LC and Lock TimeoutExceptions
jnadler Aug 9, 2010 12:27 PMWe 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