3 Replies Latest reply on Mar 29, 2012 6:42 AM by galder.zamarreno

    ERROR: ISPN000136: Execution error - org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]

    psurma

      I have a small test (attached) in which I am using REPLICATION mode and READ_COMMITTED isolation level, this test reproduces behaviour in our application which runs in JBoss 6.0.0-Final (ISPN 4.2.0), however is also reproducable here with Infinispan 5.1.2-FINAL.

       

      The test is a modification of the Infinispan Quickstart clustered-cache demo and consists of 2 nodes (running in separate JVM's on the same machine).  However, the test can also be run on 2 networked machines and also produces the same error/result.

       

      Each node attempts to store simple (String) values into an infinispan cache, if the value already exists in the cache it is skipped.

       

      for (Integer i = 1; i <= 10000; i++) {
           String k = i.toString();
           System.out.format("node:[%d] Storing key:[%4s]... ", getNodeId(), k);
      
           String val = cache.get(k);
           if (val != null) {                     
                System.out.format("already exists in cache, value:[%s]\r\n", val);                     
                continue;                
           }                
           else {                     
                System.out.format("Storing...");
      
                if (null != cache.putIfAbsent(k, "value" + getNodeId())) {
                     System.out.format("failed to put value, already exists.  value:[%s]\r\n", val);
                     continue;
                }
      
                System.out.format("OK\r\n");
           }
      }
      

       

      The test will never complete as Infinispan will throw a timeout exception when each node attempts to store the same value.

       

      Snippet from Node0:

      node:[0] Storing key:[ 814]... Storing...OK
      node:[0] Storing key:[ 815]... Storing...OK
      node:[0] Storing key:[ 816]... Storing...21-Mar-2012 13:00:40 org.infinispan.interceptors.InvocationContextInterceptor handleAll
      ERROR: ISPN000136: Execution error
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [816] for requestor [Thread[OOB-2,WINDOWS7-44777,5,Thread Pools]]! Lock held by [(another thread)]
              at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:206)
              at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:189)
              at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
              at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:67)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWriteCommand(StateTransferLockInterceptor.java:180)
              at org.infinispan.interceptors.StateTransferLockInterceptor.visitPutKeyValueCommand(StateTransferLockInterceptor.java:151)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
              at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
              at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:66)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:217)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:197)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
              at org.jgroups.JChannel.up(JChannel.java:716)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)
              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
              at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)
              at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)
              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)
              at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)
              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)
              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
              at org.jgroups.protocols.Discovery.up(Discovery.java:355)
              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)
              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)
              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
              at java.lang.Thread.run(Thread.java:662)
      21-Mar-2012 13:00:40 org.infinispan.interceptors.InvocationContextInterceptor handleAll
      ERROR: ISPN000136: Execution error
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [816] for requestor [Thread[OOB-1,WINDOWS7-22759,5,Thread Pools]]! Lock held by [(another thread)]
              at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:206)
              at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:189)
              at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
              at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:67)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWriteCommand(StateTransferLockInterceptor.java:180)
              at org.infinispan.interceptors.StateTransferLockInterceptor.visitPutKeyValueCommand(StateTransferLockInterceptor.java:151)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
              at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
              at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:66)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:217)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:197)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
              at org.jgroups.JChannel.up(JChannel.java:716)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)
              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
              at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)
              at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)
              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)
              at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)
              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)
              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
              at org.jgroups.protocols.Discovery.up(Discovery.java:355)
              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)
              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)
              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
              at java.lang.Thread.run(Thread.java:662)
      Exception in thread "main" org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [816] for requestor [Thread[OOB-1,WINDOWS7-22759,5,Thread Pools]]! Lock held by [(another thread)]
              at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:206)
              at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:189)
              at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
              at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:67)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWriteCommand(StateTransferLockInterceptor.java:180)
              at org.infinispan.interceptors.StateTransferLockInterceptor.visitPutKeyValueCommand(StateTransferLockInterceptor.java:151)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
              at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
              at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:66)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:217)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:197)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
              at org.jgroups.JChannel.up(JChannel.java:716)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)
              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
              at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)
              at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)
              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)
              at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)
              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)
              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
              at org.jgroups.protocols.Discovery.up(Discovery.java:355)
              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)
              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)
              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
              at java.lang.Thread.run(Thread.java:662)
      

       

      Snippet from Node1:

       

      node:[1] Storing key:[ 814]... already exists in cache, value:[value0]
      node:[1] Storing key:[ 815]... already exists in cache, value:[value0]
      node:[1] Storing key:[ 816]... Storing...21-Mar-2012 13:00:40 org.infinispan.interceptors.InvocationContextInterceptor handleAll
      ERROR: ISPN000136: Execution error
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [816] for requestor [Thread[OOB-1,WINDOWS7-22759,5,Thread Pools]]! Lock held by [(another thread)]
              at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:206)
              at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:189)
              at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
              at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:67)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWriteCommand(StateTransferLockInterceptor.java:180)
              at org.infinispan.interceptors.StateTransferLockInterceptor.visitPutKeyValueCommand(StateTransferLockInterceptor.java:151)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
              at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
              at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:66)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:217)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:197)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
              at org.jgroups.JChannel.up(JChannel.java:716)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)
              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
              at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)
              at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)
              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)
              at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)
              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)
              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
              at org.jgroups.protocols.Discovery.up(Discovery.java:355)
              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)
              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)
              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
              at java.lang.Thread.run(Thread.java:662)
      21-Mar-2012 13:00:40 org.infinispan.interceptors.InvocationContextInterceptor handleAll
      ERROR: ISPN000136: Execution error
      org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [816] for requestor [Thread[OOB-2,WINDOWS7-44777,5,Thread Pools]]! Lock held by [(another thread)]
              at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:206)
              at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:189)
              at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
              at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:67)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWriteCommand(StateTransferLockInterceptor.java:180)
              at org.infinispan.interceptors.StateTransferLockInterceptor.visitPutKeyValueCommand(StateTransferLockInterceptor.java:151)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
              at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
              at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:66)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:217)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:197)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
              at org.jgroups.JChannel.up(JChannel.java:716)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)
              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
              at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)
              at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)
              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)
              at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)
              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)
              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
              at org.jgroups.protocols.Discovery.up(Discovery.java:355)
              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)
              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)
              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
              at java.lang.Thread.run(Thread.java:662)
      Exception in thread "main" org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds] on key [816] for requestor [Thread[OOB-2,WINDOWS7-44777,5,Thread Pools]]! Lock held by [(another thread)]
              at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:206)
              at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:189)
              at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
              at org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutKeyValueCommand(NonTransactionalLockingInterceptor.java:67)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207)
              at org.infinispan.interceptors.StateTransferLockInterceptor.handleWriteCommand(StateTransferLockInterceptor.java:180)
              at org.infinispan.interceptors.StateTransferLockInterceptor.visitPutKeyValueCommand(StateTransferLockInterceptor.java:151)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89)
              at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
              at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
              at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:66)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
              at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:217)
              at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:197)
              at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
              at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
              at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
              at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
              at org.jgroups.JChannel.up(JChannel.java:716)
              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)
              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
              at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)
              at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)
              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)
              at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)
              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)
              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
              at org.jgroups.protocols.Discovery.up(Discovery.java:355)
              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)
              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)
              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
              at java.lang.Thread.run(Thread.java:662)
      

       

      The test can be compiled with Maven:

       

      mvn clean compile dependency:copy-dependencies -DstripVersion
      

       

      and run on each node with the following (for Windows):

       

      for the first console window:

      java -cp target\classes;target\dependency\* com.ispntest.Node0
      

       

      and in a separate console:

      java -cp target\classes;target\dependency\* com.ispntest.Node1
      

       

      The test includes various JGroups configurations (UDP/TCP taken from infinispan-core.jar), but all produce the same result.  I have tried adjusting the JGroups parameters but to no avail.

       

      The Infinispan configuration is minimal:

       

      <infinispan xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:infinispan:config:5.1 http://www.infinispan.org/schemas/infinispan-config-5.1.xsd" xmlns="urn:infinispan:config:5.1">
      
                <global>
                          <transport clusterName="demoCluster">
                                    <properties>
                                              <property name="configurationFile" value="jgroups-udp.xml"/>
                                    </properties>
                          </transport>
                </global>
      
                <default>
                          <locking isolationLevel="READ_COMMITTED" useLockStriping="false" />
      
                           <clustering mode="replication">
                                    <sync />
                          </clustering>
                </default>
         
                <namedCache name="xml-configured-cache">
                </namedCache>
      
      </infinispan>
      

       

      I am using Java 1.6.0_27

       

      Does anyone have any idea as to why a timeout exception occurs or how the test can be changed to complete its run of storing 10000 unique keys into the cache.

       

      The goal of the test is to store unique keys in all nodes (as fast as possible), so if one (or more) nodes fail, the entire cache will be available on the remaining nodes.

       

       

      Thanks for your time.

        • 1. Re: ERROR: ISPN000136: Execution error - org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
          mlinhard

          Hi Peter,

           

          the exception is there because both nodes try to PUT a value into the cache at the same time. putIfAbsent is prone to the same deadlock as the regular put.

          Both nodes 0 and 1 wanted to store the key 816 at the same time. They locked it locally and then went to replicate it via RPC, but the rpc call was blocked by waiting on lock release on the other side.

          There was cyclic waiting until both ends timeouted. In use case like this - where you write to the cache concurrently under the same key, these deadlocks are quite expected. You could lower the timeout, catch the timeoutexception, wait some random time (or nodeId * x millliseconds) and then try again. something like this:

           

                mainloop: for (Integer i = 1; i <= 10000; i++) {
                   String k = i.toString();
          
          
                   System.out.format("node:[%d] Storing key:[%4s]... ", getNodeId(), k);
          
          
                   String val = cache.get(k);
                   while (val == null) {
                      System.out.format("Storing...");
                      try {
                         if (null != cache.putIfAbsent(k, "value" + getNodeId())) {
                            System.out.format("failed to put value, already exists.  value:[%s]\r\n", val);
                         } else {
                            System.out.format("OK\r\n");
                         }
                         continue mainloop;
                      } catch (TimeoutException e) {
                         System.out.format("failed to put value, due to concurrent access. value:[%s]\r\n",
                                  val);
                         try {
                            Thread.sleep(100 * getNodeId());
                         } catch (InterruptedException e1) {
                            log.error("Error", e1);
                         }
                         val = cache.get(k);
                      }
                   }
                   System.out.format("already exists in cache, value:[%s]\r\n", val);
                }
          

           

          But you will till get these errors and it might take quite long until the cache fills the 10000 values this way.

          • 2. Re: ERROR: ISPN000136: Execution error - org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
            psurma

            Thank you for your reply Michal.

             

            If deadlocks are occurring, do you know why the following addition to infinispan.xml has no effect on the test?

             

            <deadlockDetection enabled="true"/>
            

             

             

            I have actually discovered that if I add the following configuration to my cache:

             

             

                     <transaction
                           transactionManagerLookupClass="org.infinispan.transaction.lookup.GenericTransactionManagerLookup"
                           syncRollbackPhase="false"
                           syncCommitPhase="false"
                           useEagerLocking="true">
            

             

            I get no locking exceptions at all - but only with 5.1.2.Final/5.1.3.Final

             

            In 4.2.x it makes no difference to the test.

             

            Alternatively I can add:

             

            <invocationBatching enabled="true"/>
            

             

            and again,the test will run with no exceptions!

             

            This however requires an upgrade of Infinispan from 4.2.x to 5.1.x in JBoss 6.0.0, which is easier said than done!  Otherwise, move to JBoss 7.1.x, however due to problems with integrating ActiveMQ 5.5.1, we cannot do so.

             

            For now we have disabled Infinispan 4..2.x from JBoss 6 and are deploying ISPN in our ear.

            • 3. Re: ERROR: ISPN000136: Execution error - org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
              galder.zamarreno

              Please note that useEagerLocking configuration option has been deprecated in 5.1. Instead, please set: lockingMode="PESSIMISTIC" - see https://docs.jboss.org/author/x/FAY5