[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
[ https://issues.jboss.org/browse/WFLY-6877?page=com.atlassian.jira.plugin.... ]
Sammy Chu updated WFLY-6877:
----------------------------
Description:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:37,971 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-33) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY] for owner=GlobalTransaction:<10.1.3.29>:492:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
was:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
> Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6877
> URL: https://issues.jboss.org/browse/WFLY-6877
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Environment: Wildfly 10.0.0-Final
> JDK 1.8.0_66-b17
> Linux
> Reporter: Sammy Chu
> Assignee: Paul Ferraro
> Priority: Critical
> Attachments: FineSessionAttributes.java
>
>
> Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
> {code:xml}
> <cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
> <transport lock-timeout="60000"/>
> <distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
> <locking isolation="REPEATABLE_READ"/>
> <transaction locking="OPTIMISTIC" mode="BATCH"/>
> <file-store/>
> </distributed-cache>
> </cache-container>
> {code}
> When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
> {noformat}
> 2016-07-21 13:01:37,971 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-33) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY] for owner=GlobalTransaction:<10.1.3.29>:492:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
> at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
> at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
> at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
> at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
> at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
> at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
> at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
> at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
> {noformat}
> 2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
> {noformat}
> We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
> After future tracing, we found the following log message on another cluster node:
> {noformat}
> 2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
> {noformat}
> In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
> The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
> Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
[ https://issues.jboss.org/browse/WFLY-6877?page=com.atlassian.jira.plugin.... ]
Sammy Chu updated WFLY-6877:
----------------------------
Description:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
was:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->com.ecv.component.profile.User and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
> Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6877
> URL: https://issues.jboss.org/browse/WFLY-6877
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Environment: Wildfly 10.0.0-Final
> JDK 1.8.0_66-b17
> Linux
> Reporter: Sammy Chu
> Assignee: Paul Ferraro
> Priority: Critical
> Attachments: FineSessionAttributes.java
>
>
> Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
> {code:xml}
> <cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
> <transport lock-timeout="60000"/>
> <distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
> <locking isolation="REPEATABLE_READ"/>
> <transaction locking="OPTIMISTIC" mode="BATCH"/>
> <file-store/>
> </distributed-cache>
> </cache-container>
> {code}
> When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
> {noformat}
> 2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
> at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
> at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
> at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
> at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
> at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
> at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
> at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
> at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
> {noformat}
> 2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
> {noformat}
> We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
> After future tracing, we found the following log message on another cluster node:
> {noformat}
> 2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
> {noformat}
> In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
> The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
> Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
[ https://issues.jboss.org/browse/WFLY-6877?page=com.atlassian.jira.plugin.... ]
Sammy Chu updated WFLY-6877:
----------------------------
Description:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) {batch38003(a)e.com} ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->com.ecv.component.profile.User and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
was:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
> Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6877
> URL: https://issues.jboss.org/browse/WFLY-6877
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Environment: Wildfly 10.0.0-Final
> JDK 1.8.0_66-b17
> Linux
> Reporter: Sammy Chu
> Assignee: Paul Ferraro
> Priority: Critical
> Attachments: FineSessionAttributes.java
>
>
> Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
> {code:xml}
> <cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
> <transport lock-timeout="60000"/>
> <distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
> <locking isolation="REPEATABLE_READ"/>
> <transaction locking="OPTIMISTIC" mode="BATCH"/>
> <file-store/>
> </distributed-cache>
> </cache-container>
> {code}
> When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
> {noformat}
> 2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) {batch38003(a)e.com} ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->com.ecv.component.profile.User and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
> at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
> at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
> at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
> at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
> at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
> at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
> at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
> at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
> {noformat}
> 2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
> {noformat}
> We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
> After future tracing, we found the following log message on another cluster node:
> {noformat}
> 2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
> {noformat}
> In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
> The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
> Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
[ https://issues.jboss.org/browse/WFLY-6877?page=com.atlassian.jira.plugin.... ]
Sammy Chu updated WFLY-6877:
----------------------------
Description:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->com.ecv.component.profile.User and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
was:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) {batch38003(a)e.com} ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->com.ecv.component.profile.User and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
> Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6877
> URL: https://issues.jboss.org/browse/WFLY-6877
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Environment: Wildfly 10.0.0-Final
> JDK 1.8.0_66-b17
> Linux
> Reporter: Sammy Chu
> Assignee: Paul Ferraro
> Priority: Critical
> Attachments: FineSessionAttributes.java
>
>
> Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
> {code:xml}
> <cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
> <transport lock-timeout="60000"/>
> <distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
> <locking isolation="REPEATABLE_READ"/>
> <transaction locking="OPTIMISTIC" mode="BATCH"/>
> <file-store/>
> </distributed-cache>
> </cache-container>
> {code}
> When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
> {noformat}
> 2016-07-21 13:01:52,975 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-33) ISPN000136: Error executing command PrepareCommand, writing keys [4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->com.ecv.component.profile.User and requestor GlobalTransaction:<10.1.3.29>:492:local. Lock is held by GlobalTransaction:<10.1.3.29>:458:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
> at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
> at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
> at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
> at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
> at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
> at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
> at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
> at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
> {noformat}
> 2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
> {noformat}
> We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
> After future tracing, we found the following log message on another cluster node:
> {noformat}
> 2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
> {noformat}
> In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
> The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
> Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
[ https://issues.jboss.org/browse/WFLY-6877?page=com.atlassian.jira.plugin.... ]
Sammy Chu updated WFLY-6877:
----------------------------
Description:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
was:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to log the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
> Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6877
> URL: https://issues.jboss.org/browse/WFLY-6877
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Environment: Wildfly 10.0.0-Final
> JDK 1.8.0_66-b17
> Linux
> Reporter: Sammy Chu
> Assignee: Paul Ferraro
> Priority: Critical
> Attachments: FineSessionAttributes.java
>
>
> Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
> {code:xml}
> <cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
> <transport lock-timeout="60000"/>
> <distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
> <locking isolation="REPEATABLE_READ"/>
> <transaction locking="OPTIMISTIC" mode="BATCH"/>
> <file-store/>
> </distributed-cache>
> </cache-container>
> {code}
> When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
> {noformat}
> 2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
> at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
> at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
> at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
> at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
> at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
> at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
> at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
> at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to lock the same key within that interval, it will result in the timeout exception, example as below:
> {noformat}
> 2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
> {noformat}
> We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
> After future tracing, we found the following log message on another cluster node:
> {noformat}
> 2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
> {noformat}
> In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
> The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
> Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
Sammy Chu created WFLY-6877:
-------------------------------
Summary: Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
Key: WFLY-6877
URL: https://issues.jboss.org/browse/WFLY-6877
Project: WildFly
Issue Type: Bug
Components: Clustering
Affects Versions: 10.0.0.Final
Environment: Wildfly 10.0.0-Final
JDK 1.8.0_66-b17
Linux
Reporter: Sammy Chu
Assignee: Paul Ferraro
Priority: Critical
Attachments: FineSessionAttributes.java
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{/code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to log the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6877) Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
by Sammy Chu (JIRA)
[ https://issues.jboss.org/browse/WFLY-6877?page=com.atlassian.jira.plugin.... ]
Sammy Chu updated WFLY-6877:
----------------------------
Description:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to log the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
was:
Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
{code:xml}
<cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
<transport lock-timeout="60000"/>
<distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
<locking isolation="REPEATABLE_READ"/>
<transaction locking="OPTIMISTIC" mode="BATCH"/>
<file-store/>
</distributed-cache>
</cache-container>
{/code}
When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
{noformat}
2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to log the same key within that interval, it will result in the timeout exception, example as below:
{noformat}
2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
{noformat}
We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
After future tracing, we found the following log message on another cluster node:
{noformat}
2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
{noformat}
In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
> Fine session attributes (i.e. replication-granularity = ATTRIBUTE) cause org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6877
> URL: https://issues.jboss.org/browse/WFLY-6877
> Project: WildFly
> Issue Type: Bug
> Components: Clustering
> Affects Versions: 10.0.0.Final
> Environment: Wildfly 10.0.0-Final
> JDK 1.8.0_66-b17
> Linux
> Reporter: Sammy Chu
> Assignee: Paul Ferraro
> Priority: Critical
> Attachments: FineSessionAttributes.java
>
>
> Our system using the following infinispan configuration for web session cache (i.e. an async, non-transactional, batch, optimistic locking dustrubutable cache):
> {code:xml}
> <cache-container name="web" default-cache="dist" module="org.wildfly.clustering.web.infinispan">
> <transport lock-timeout="60000"/>
> <distributed-cache name="dist" mode="ASYNC" l1-lifespan="0" owners="2">
> <locking isolation="REPEATABLE_READ"/>
> <transaction locking="OPTIMISTIC" mode="BATCH"/>
> <file-store/>
> </distributed-cache>
> </cache-container>
> {code}
> When we perform a load test for one of our business use case in our system, Wildfly always throw the infamous locking for 15 seconds timeout exception:
> {noformat}
> 2016-07-14 16:44:11,585 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-45) ISPN000136: Error executing command PrepareCommand, writing keys [UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->XXX, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->YYY, UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UN3iNlvQSwNtgsNO83cjL4hy8OpV9PYAT_PuUFml->ZZZ and requestor GlobalTransaction:<10.1.3.29>:22896:local. Lock is held by GlobalTransaction:<10.1.3.29>:21594:local
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
> at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$CompositeLockPromise.lock(DefaultLockManager.java:305)
> at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAllAndRecord(AbstractLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockAllKeys(AbstractTxLockingInterceptor.java:199)
> at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAllOrRegisterBackupLock(AbstractTxLockingInterceptor.java:165)
> at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:69)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:157)
> at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:144)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:42)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:238)
> at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:87)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:112)
> at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:173)
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
> at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:389)
> at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:435)
> at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:314)
> at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:105)
> at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73)
> at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48)
> at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:77)
> at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:768)
> at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:557)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:331)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> After tracing using the trace log, we found the time difference between a "Lock all keys" log statement and the "Release locks for keys" log statement takes for about 15~20 seconds, so if another concurrent request would like to log the same key within that interval, it will result in the timeout exception, example as below:
> {noformat}
> 2016-07-21 13:01:37,958 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Lock all keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl] for owner=GlobalTransaction:<10.1.3.29>:458:local. timeout=15000 (MILLISECONDS)
> 2016-07-21 13:01:53,364 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-37) Release locks for keys=[4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, 4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl]. owner=GlobalTransaction:<10.1.3.29>:458:local
> {noformat}
> We think that is strange as those session keys are POJO without complex nested objects, and we only perform read operation on those objects. Although we know objects without marked *(a)org.wildfly.clustering.web.annotation.Immutable* will perform cache sync, we believe that should not took for more than 1 second to commit the cache but it takes for more than 15 seconds...
> After future tracing, we found the following log message on another cluster node:
> {noformat}
> 2016-07-21 13:01:53,410 TRACE [org.infinispan.commands.tx.PrepareCommand] (Incoming-10,ee,10.1.3.30) {} Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@f9f09c2, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@f72eca9, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ, value=[B@6f108f88, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl, value=org.wildfly.clustering.web.infinispan.session.SimpleSessionAccessMetaData@126bb5d4, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->XXX, value=[B@1a574fb5, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->YYY, value=[B@3141bcb, flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, PutKeyValueCommand{key=4V3S9Lw0pGPAK3wt8bYEt3BK06iimxk88geCH2Gl->ZZZ.menuName, value=[B@ae3a302, flags=[FORCE_SYNCHRONOUS], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}, ...], onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<10.1.3.29>:458:remote, cacheName='app.war', topologyId=2} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext@3d21e5e9
> {noformat}
> In general, it synchronized XXX key {color:red}2{color} times, YYY key {color:red}2272{color} times, ZZZ key {color:red}3{color} times!!!
> The root cause should be this line: https://github.com/wildfly/wildfly/blob/10.0.0.Final/clustering/web/infin... where a new CacheEntryMutator.mutate() will trigger a new PutKeyValueCommand, but that is not necessary for transactional/ batched cache in general as the MarshalledValue is lazily serialized, the actual value is pointing to the same instance.
> Attached the suggested change, which solved our issue. Basically use a Set to track the mutated attribute names, to ensure the command is only issued once. Tested on non-transactional, batched cache (non-transactional, non-batch cache may not work as I did not think about that...)
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6876) Unessesary allocation in JACCContextIdHandler
by Stuart Douglas (JIRA)
Stuart Douglas created WFLY-6876:
------------------------------------
Summary: Unessesary allocation in JACCContextIdHandler
Key: WFLY-6876
URL: https://issues.jboss.org/browse/WFLY-6876
Project: WildFly
Issue Type: Bug
Reporter: Stuart Douglas
Assignee: Jason Greene
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6865) org.jboss.modules.ModuleNotFoundException when setting annotations=true in jboss-deployment-structure.xml
by Stuart Douglas (JIRA)
[ https://issues.jboss.org/browse/WFLY-6865?page=com.atlassian.jira.plugin.... ]
Stuart Douglas reassigned WFLY-6865:
------------------------------------
Assignee: Stuart Douglas (was: Jason Greene)
> org.jboss.modules.ModuleNotFoundException when setting annotations=true in jboss-deployment-structure.xml
> ---------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6865
> URL: https://issues.jboss.org/browse/WFLY-6865
> Project: WildFly
> Issue Type: Bug
> Components: Server
> Reporter: Brad Maxwell
> Assignee: Stuart Douglas
> Attachments: reproducer.zip
>
>
> {code}
> helloWorld.ear
> - helloWorld-ejb.jar
> - HelloBean - @Stateless EJB extends AbstractBean
> - lib
> - helloWorld-api.jar
> - META-INF
> - jandex.idx
> - Hello - EJB interface
> - AbstractBean - abstract class which has @PostConstruct and implements Hello
> helloWorld2.ear
> - helloWorld2-ejb.jar
> - HelloBean2 - @Startup @Singleton extends AbstractBean
> - META-INF
> - jboss-deployment-structure.xml depends on deployment.helloWorld.ear export=true annotations=true
> {code}
> To have HelloBean2 pickup the annotations on AbstractBean, jandex.idx was generate for the helloWorld-api.jar and then the j-d-s.xml file dependency has export=true so helloWorld2-ejb.jar sees the classes and annotations=true set to pull in the annotations.
> When annotations is not set or annotations=false the helloWorld2.ear deploys (but the @PostConstruct is not run since annotations are not enabled). When annotations=true is set, helloWorld2.ear fails to deploy with the exception below.
> It looks like the annotations handling is possibly out of order as the j-d-s.xml dependency should ensure the deployment.helloWorld.ear module is there (which it does when annotations=false, but when true it seems the module is not ready)
> {code}
> 19:44:44,659 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-2) MSC000001: Failed to start service jboss.deployment.unit."helloWorld2.ear".PARSE: org.jboss.msc.service.StartException in service jboss.deployment.unit."helloWorld2.ear".PARSE: WFLYSRV0153: Failed to process phase PARSE of deployment "helloWorld2.ear"
> at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:154)
> at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1948)
> at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1881)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: org.jboss.as.server.deployment.DeploymentUnitProcessingException: org.jboss.modules.ModuleNotFoundException: deployment.helloWorld.ear:main
> at org.jboss.as.server.deployment.annotation.CompositeIndexProcessor.deploy(CompositeIndexProcessor.java:91)
> at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:147)
> ... 5 more
> Caused by: org.jboss.modules.ModuleNotFoundException: deployment.helloWorld.ear:main
> at org.jboss.modules.ModuleLoader.loadModule(ModuleLoader.java:223)
> at org.jboss.as.server.deployment.annotation.CompositeIndexProcessor.deploy(CompositeIndexProcessor.java:81)
> ... 6 more
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0
[JBoss JIRA] (WFLY-6865) org.jboss.modules.ModuleNotFoundException when setting annotations=true in jboss-deployment-structure.xml
by Stuart Douglas (JIRA)
[ https://issues.jboss.org/browse/WFLY-6865?page=com.atlassian.jira.plugin.... ]
Stuart Douglas commented on WFLY-6865:
--------------------------------------
The issue is that annotation processing happens much earlier in the deployment processing, so dependencies are not established yet.
> org.jboss.modules.ModuleNotFoundException when setting annotations=true in jboss-deployment-structure.xml
> ---------------------------------------------------------------------------------------------------------
>
> Key: WFLY-6865
> URL: https://issues.jboss.org/browse/WFLY-6865
> Project: WildFly
> Issue Type: Bug
> Components: Server
> Reporter: Brad Maxwell
> Assignee: Stuart Douglas
> Attachments: reproducer.zip
>
>
> {code}
> helloWorld.ear
> - helloWorld-ejb.jar
> - HelloBean - @Stateless EJB extends AbstractBean
> - lib
> - helloWorld-api.jar
> - META-INF
> - jandex.idx
> - Hello - EJB interface
> - AbstractBean - abstract class which has @PostConstruct and implements Hello
> helloWorld2.ear
> - helloWorld2-ejb.jar
> - HelloBean2 - @Startup @Singleton extends AbstractBean
> - META-INF
> - jboss-deployment-structure.xml depends on deployment.helloWorld.ear export=true annotations=true
> {code}
> To have HelloBean2 pickup the annotations on AbstractBean, jandex.idx was generate for the helloWorld-api.jar and then the j-d-s.xml file dependency has export=true so helloWorld2-ejb.jar sees the classes and annotations=true set to pull in the annotations.
> When annotations is not set or annotations=false the helloWorld2.ear deploys (but the @PostConstruct is not run since annotations are not enabled). When annotations=true is set, helloWorld2.ear fails to deploy with the exception below.
> It looks like the annotations handling is possibly out of order as the j-d-s.xml dependency should ensure the deployment.helloWorld.ear module is there (which it does when annotations=false, but when true it seems the module is not ready)
> {code}
> 19:44:44,659 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-2) MSC000001: Failed to start service jboss.deployment.unit."helloWorld2.ear".PARSE: org.jboss.msc.service.StartException in service jboss.deployment.unit."helloWorld2.ear".PARSE: WFLYSRV0153: Failed to process phase PARSE of deployment "helloWorld2.ear"
> at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:154)
> at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1948)
> at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1881)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: org.jboss.as.server.deployment.DeploymentUnitProcessingException: org.jboss.modules.ModuleNotFoundException: deployment.helloWorld.ear:main
> at org.jboss.as.server.deployment.annotation.CompositeIndexProcessor.deploy(CompositeIndexProcessor.java:91)
> at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:147)
> ... 5 more
> Caused by: org.jboss.modules.ModuleNotFoundException: deployment.helloWorld.ear:main
> at org.jboss.modules.ModuleLoader.loadModule(ModuleLoader.java:223)
> at org.jboss.as.server.deployment.annotation.CompositeIndexProcessor.deploy(CompositeIndexProcessor.java:81)
> ... 6 more
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 5 months
- 1
- 0