TimeoutException on local non-transactional cache

[cstillwell]

From time to time we are seeing some TimeoutExceptions on local non-transactional caches.  Most of the timeouts I have found searching for this seem to be related to replicated or distributed caches and not for local caches.

We are running wildfly-8.1.0.CR1 so have infinispan 6.0.2.  Any suggestions on how to debug this would be appreciated.  We are not doing anything special, just putIfAbsent, gets, and removes.

Thanks,

Chris

Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [TP MAD  BHZ  ] for requestor [GlobalTransaction:<null>:57177170:local]! Lock held by [GlobalTransaction:<null>:57176600:local]

    at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:169) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitPutKeyValueCommand(PessimisticLockingInterceptor.java:107) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:186) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:148) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:134) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:66) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1306) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.CacheImpl.putIfAbsentInternal(CacheImpl.java:903) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.CacheImpl.putIfAbsent(CacheImpl.java:893) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.CacheImpl.putIfAbsent(CacheImpl.java:1366) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.CacheImpl.putIfAbsent(CacheImpl.java:245) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

    at org.infinispan.AbstractDelegatingCache.putIfAbsent(AbstractDelegatingCache.java:231) [infinispan-core-6.0.2.Final.jar:6.0.2.Final]

[william.burns]

From the stack trace I can say that this is a transactional cache that is experiencing the timeout.  It seems your configuration is not being applied?  Either that or maybe the cache name doesn't match in the configuration?

[cstillwell]

Thanks for the reply.  You are correct that it was actually a transactional cache.  The cache was defined inside a jboss standalone.xml cache container.  Looking at the schema I saw that the default for transaction mode was NONE and thought that's what I had.  Looking at the cache with a debugger I saw that it was indeed created as transactional.  Turns out we also had batching true, which requires transactions.  I changed batching to false and verified in the debugger that the cache is now non-transactional.  I have not noticed any timeouts since then.

Chris