ERROR: ISPN000136: Execution error - org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
psurma Mar 21, 2012 9:55 AMI 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.
-
ispntest.zip 16.4 KB