[
https://issues.jboss.org/browse/ISPN-2240?page=com.atlassian.jira.plugin....
]
Robert Stupp edited comment on ISPN-2240 at 1/14/13 11:24 AM:
--------------------------------------------------------------
A first result from our test:
* works, if we do not use a {{Cache.putAll}} method (just a lot of {{Cache.put()}}
operations)
* still produces {{TimeoutException}} s if we use a {{Cache.putAll}} - but the
"original" requests (originating the {{putAll}} do not fail):
{noformat}
2013-01-14 17:08:46,224 WARN [OPERATION] (http-threads - 23 - client:10.80.191.33:9180)
FatalException:
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
on key [...] for requestor [Thread[OOB-48,det-servicelayer-as-51-65400,5,Thread Pools]]!
Lock held by [Thread[frw-main-executor-47,5,main]]
at
org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:217)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:200)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutMapCommand(NonTransactionalLockingInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.AbstractVisitor.visitPutMapCommand(AbstractVisitor.java:82)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:194)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.statetransfer.StateTransferInterceptor.visitPutMapCommand(StateTransferInterceptor.java:141)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.CacheMgmtInterceptor.visitPutMapCommand(CacheMgmtInterceptor.java:113)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.AbstractVisitor.visitPutMapCommand(AbstractVisitor.java:82)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:101)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:122)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:86)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:245)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:218)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:483)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:390)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:248)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at
org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:598)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.JChannel.up(JChannel.java:703)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.RSVP.up(RSVP.java:188)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FRAG2.unfragment(FRAG2.java:302)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:162)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:736)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:414)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.TP.passMessageUp(TP.java:1287)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1850)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1823)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[rt.jar:1.6.0_31]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[rt.jar:1.6.0_31]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_31]
Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after
[10 seconds] on key [...] for requestor
[Thread[OOB-48,det-servicelayer-as-51-65400,5,Thread Pools]]! Lock held by
[Thread[frw-main-executor-47,5,main]]
... 55 more
{noformat}
Configuration is:
* JBoss AS 7.1.1
* Infinispan 5.2.0.CR1 (deployed inside EAR lib)
* 4 servers - each part of the infinispan cluster
* 4 load test clients each requesting the same data set, which is splitted into sets of N
entries (N = 1 or 50 or 100, etc)
* Each request is randomly distributed to one of the backend servers
* There is some possibility that 2 or more concurrent requests request the same set of
entries which are not already caches and added to the cache concurrently
* Cache instances are inquired from {{DefaultCacheManager.getCache()}}
was (Author: snazy):
A first result from our test:
* works, if we do not use a {{Cache.putAll}} method (just a lot of {{Cache.put()}}
operations
* still produces {{TimeoutException}}s if we use a {{Cache.putAll}} - but the
"original" requests (originating the {{putAll}} do not fail):
{noformat}
2013-01-14 17:08:46,224 WARN [OPERATION] (http-threads - 23 - client:10.80.191.33:9180)
FatalException:
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
on key [...] for requestor [Thread[OOB-48,det-servicelayer-as-51-65400,5,Thread Pools]]!
Lock held by [Thread[frw-main-executor-47,5,main]]
at
org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:217)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:200)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor.visitPutMapCommand(NonTransactionalLockingInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.AbstractVisitor.visitPutMapCommand(AbstractVisitor.java:82)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:194)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.statetransfer.StateTransferInterceptor.visitPutMapCommand(StateTransferInterceptor.java:141)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.CacheMgmtInterceptor.visitPutMapCommand(CacheMgmtInterceptor.java:113)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.AbstractVisitor.visitPutMapCommand(AbstractVisitor.java:82)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.write.PutMapCommand.acceptVisitor(PutMapCommand.java:68)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:101)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:122)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:86)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:245)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at
org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:218)
[infinispan-core-5.2.0.CR1.jar:5.2.0.CR1]
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:483)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:390)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:248)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at
org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:598)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.JChannel.up(JChannel.java:703)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.RSVP.up(RSVP.java:188)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FRAG2.unfragment(FRAG2.java:302)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:162)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:736)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:414)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.TP.passMessageUp(TP.java:1287)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1850)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1823)
[jgroups-3.2.5.Final.jar:3.2.5.Final]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[rt.jar:1.6.0_31]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[rt.jar:1.6.0_31]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_31]
Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after
[10 seconds] on key [...] for requestor
[Thread[OOB-48,det-servicelayer-as-51-65400,5,Thread Pools]]! Lock held by
[Thread[frw-main-executor-47,5,main]]
... 55 more
{noformat}
Configuration is:
* JBoss AS 7.1.1
* Infinispan 5.2.0.CR1 (deployed inside EAR lib)
* 4 servers - each part of the infinispan cluster
* 4 load test clients each requesting the same data set, which is splitted into sets of N
entries (N = 1 or 50 or 100, etc)
* Each request is randomly distributed to one of the backend servers
* There is some possibility that 2 or more concurrent requests request the same set of
entries which are not already caches and added to the cache concurrently
* Cache instances are inquired from {{DefaultCacheManager.getCache()}}
Per-key lock container leads to superfluous TimeoutExceptions on
concurrent access to same key
----------------------------------------------------------------------------------------------
Key: ISPN-2240
URL:
https://issues.jboss.org/browse/ISPN-2240
Project: Infinispan
Issue Type: Bug
Components: Locking and Concurrency
Affects Versions: 5.1.6.FINAL, 5.1.x
Reporter: Robert Stupp
Assignee: Mircea Markus
Priority: Critical
Fix For: 5.2.0.Final
Attachments: ISPN-2240_fix_TimeoutExceptions.patch, somehow.zip
Hi,
I've encountered a lot of TimeoutExceptions just running a load test against an
infinispan cluster.
I tracked down the reason and found out, that the code in
org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer#releaseLock()
causes these superfluous TimeoutExceptions.
A small test case (which just prints out timeouts, too late timeouts and
"paints" a lot of dots to the console - more dots/second on the console means
better throughput ;-)
In a short test I extended the class ReentrantPerEntryLockContainer and changed the
implementation of releaseLock() as follows:
{noformat}
public void releaseLock(Object lockOwner, Object key) {
ReentrantLock l = locks.get(key);
if (l != null) {
if (!l.isHeldByCurrentThread())
throw new IllegalStateException("Lock for [" + key + "]
not held by current thread " + Thread.currentThread());
while (l.isHeldByCurrentThread())
unlock(l, lockOwner);
if (!l.hasQueuedThreads())
locks.remove(key);
}
else
throw new IllegalStateException("No lock for [" + key +
']');
}
{noformat}
The main improvement is that locks are not removed from the concurrent map as long as
other threads are waiting on that lock.
If the lock is removed from the map while other threads are waiting for it, they may run
into timeouts and force TimeoutExceptions to the client.
The above methods "paints more dots per second" - means: it gives a better
throughput for concurrent accesses to the same key.
The re-implemented method should also fix some replication timeout exceptions.
Please, please add this to 5.1.7, if possible.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see:
http://www.atlassian.com/software/jira