[infinispan-issues] [JBoss JIRA] (ISPN-2240) Per-key lock container leads to superfluous TimeoutExceptions on concurrent access to same key
Robert Stupp (JIRA)
jira-events at lists.jboss.org
Mon Jan 14 11:23:22 EST 2013
[ https://issues.jboss.org/browse/ISPN-2240?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12745683#comment-12745683 ]
Robert Stupp commented on ISPN-2240:
------------------------------------
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
More information about the infinispan-issues
mailing list