[jboss-user] [JBoss Cache] - org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn after [0] milliseconds- when trying to do evict on read-only cached Entity

Vikram Murugesan do-not-reply at jboss.com
Tue Nov 27 16:14:25 EST 2012 

Vikram Murugesan [https://community.jboss.org/people/vikrammurugesan] created the discussion

"org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn after [0] milliseconds- when trying to do evict on read-only cached Entity"

To view the discussion, visit: https://community.jboss.org/message/778702#778702

--------------------------------------------------------------
Hello,

We are using JBoss Cache to cache our entities in a clustered JBoss Environment (with 6 nodes mostly. sometimes use 8 nodes). We have JTA configured and most of our ENTITIES are cached in transactional strategy. But there is this one entity that is cached in read-only strategy.

This Entity is mapped to kind of a key/value pair table with just 2 columns (key and value). We maintain this entity in read-only cache intstead of transactional mode because the values in this table are being accessed multiple times. We also performed some JMeter load tests on our application and proved that transactional mode was expensive than readonly.

As this entity is marked readonly, whenever the value of one of this entity is changed, we have a inbuilt framework that does a evict on this entity on all the other JBoss nodes. This way we ensure that the value of the modified entity is the same across all nodes. But here is where we are getting a org.jboss.cache.lock.TimeoutException. If my understanding is right, this exception is thrown as all the JBoss nodes are trying to acquire a lock on the node at the same time when our inbuillt framework tries to evict the node.

To add - we use the default mvcc-entity cache config

*Version Details :*
*
*
JBoss EAP 5.1.2*
*
jbosscache - 3.2.8.GA
hibernate-jbosscache2 - 3.3.2.GA_CP04

*Here is the stacktrace :*

{code} 
14:41:10,696 WARN  [InvalidationInterceptor] Unable to broadcast evicts as a part of the prepare phase.  Rolling back.
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/path/to/entity/ENTITY/path.to.entity.ApplicationProperty#property.key.value] after [0] milliseconds for requestor [Thread[Incoming-19,135.215.109.38:55300,10,Thread Pools]]! Lock held by [GlobalTransaction:<135.215.109.38:55300>:19]
    at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:159)
    at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodesRecursivelyForRemoval(MVCCNodeHelper.java:339)
    at org.jboss.cache.interceptors.MVCCLockingInterceptor.handleInvalidateCommand(MVCCLockingInterceptor.java:203)
    at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitInvalidateCommand(PrePostProcessingCommandInterceptor.java:203)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:269)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
    at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:316)
    at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:139)
    at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:115)
    at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:319)
    at org.jboss.cache.marshall.InactiveRegionAwareRpcDispatcher.handle(InactiveRegionAwareRpcDispatcher.java:95)
    at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637)
    at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:545)
    at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:368)
    at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:775)
    at org.jgroups.JChannel.up(JChannel.java:1336)
    at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:454)
    at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:490)
    at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:153)
    at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
    at org.jgroups.protocols.FC.up(FC.java:473)
    at org.jgroups.protocols.pbcast.GMS.up(GMS.java:821)
    at org.jgroups.protocols.VIEW_SYNC.up(VIEW_SYNC.java:192)
    at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233)
    at org.jgroups.protocols.UNICAST.up(UNICAST.java:328)
    at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:895)
    at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:708)
    at org.jgroups.protocols.BARRIER.up(BARRIER.java:136)
    at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
    at org.jgroups.protocols.FD.up(FD.java:284)
    at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:328)
    at org.jgroups.protocols.MERGE2.up(MERGE2.java:144)
    at org.jgroups.protocols.Discovery.up(Discovery.java:264)
    at org.jgroups.protocols.PING.up(PING.java:273)
    at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2319)
    at org.jgroups.protocols.TP.passMessageUp(TP.java:1253)
    at org.jgroups.protocols.TP.access$100(TP.java:50)
    at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1830)
    at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1809)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)
14:41:10,704 WARN  [TxInterceptor] Caught exception, will now set transaction to roll back
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/path/to/entity/ENTITY/path.to.entity.ApplicationProperty#property.key.value] after [0] milliseconds for requestor [Thread[Incoming-19,135.215.109.38:55300,10,Thread Pools]]! Lock held by [GlobalTransaction:<135.215.109.38:55300>:19]
    at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:159)
    at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodesRecursivelyForRemoval(MVCCNodeHelper.java:339)
    at org.jboss.cache.interceptors.MVCCLockingInterceptor.handleInvalidateCommand(MVCCLockingInterceptor.java:203)
    at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitInvalidateCommand(PrePostProcessingCommandInterceptor.java:203)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:269)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
    at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:316)
    at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:139)
    at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:115)
    at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:319)
    at org.jboss.cache.marshall.InactiveRegionAwareRpcDispatcher.handle(InactiveRegionAwareRpcDispatcher.java:95)
    at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637)
    at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:545)
    at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:368)
    at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:775)
    at org.jgroups.JChannel.up(JChannel.java:1336)
    at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:454)
    at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:490)
    at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:153)
    at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
    at org.jgroups.protocols.FC.up(FC.java:473)
    at org.jgroups.protocols.pbcast.GMS.up(GMS.java:821)
    at org.jgroups.protocols.VIEW_SYNC.up(VIEW_SYNC.java:192)
    at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233)
    at org.jgroups.protocols.UNICAST.up(UNICAST.java:328)
    at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:895)
    at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:708)
    at org.jgroups.protocols.BARRIER.up(BARRIER.java:136)
    at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
    at org.jgroups.protocols.FD.up(FD.java:284)
    at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:328)
    at org.jgroups.protocols.MERGE2.up(MERGE2.java:144)
    at org.jgroups.protocols.Discovery.up(Discovery.java:264)
    at org.jgroups.protocols.PING.up(PING.java:273)
    at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2319)
    at org.jgroups.protocols.TP.passMessageUp(TP.java:1253)
    at org.jgroups.protocols.TP.access$100(TP.java:50)
    at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1830)
    at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1809)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)
14:41:10,727 WARN  [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple at e97df0 Drive beforeCompletion participants.
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/path/to/entity/ENTITY/path.to.entity.ApplicationProperty#property.key.value] after [0] milliseconds for requestor [Thread[Incoming-19,135.215.109.38:55300,10,Thread Pools]]! Lock held by [GlobalTransaction:<135.215.109.38:55300>:19]
    at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:159)
    at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodesRecursivelyForRemoval(MVCCNodeHelper.java:339)
    at org.jboss.cache.interceptors.MVCCLockingInterceptor.handleInvalidateCommand(MVCCLockingInterceptor.java:203)
    at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitInvalidateCommand(PrePostProcessingCommandInterceptor.java:203)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:269)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
    at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
    at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
    at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
    at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
    at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:316)
    at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:139)
    at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:115)
    at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:319)
    at org.jboss.cache.marshall.InactiveRegionAwareRpcDispatcher.handle(InactiveRegionAwareRpcDispatcher.java:95)
    at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637)
    at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:545)
    at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:368)
    at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:775)
    at org.jgroups.JChannel.up(JChannel.java:1336)
    at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:454)
    at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:490)
    at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:153)
    at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
    at org.jgroups.protocols.FC.up(FC.java:473)
    at org.jgroups.protocols.pbcast.GMS.up(GMS.java:821)
    at org.jgroups.protocols.VIEW_SYNC.up(VIEW_SYNC.java:192)
    at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233)
    at org.jgroups.protocols.UNICAST.up(UNICAST.java:328)
    at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:895)
    at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:708)
    at org.jgroups.protocols.BARRIER.up(BARRIER.java:136)
    at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
    at org.jgroups.protocols.FD.up(FD.java:284)
    at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:328)
    at org.jgroups.protocols.MERGE2.up(MERGE2.java:144)
    at org.jgroups.protocols.Discovery.up(Discovery.java:264)
    at org.jgroups.protocols.PING.up(PING.java:273)
    at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2319)
    at org.jgroups.protocols.TP.passMessageUp(TP.java:1253)
    at org.jgroups.protocols.TP.access$100(TP.java:50)
    at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1830)
    at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1809)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)
{code}

*Code :*

{code} HibernateUtil.getSessionFactory().evict(ApplicationProperty.class, aPropertyKey); {code}

The above code is being executed by all 6 JBoss nodes simultaneously.

Please provide your thoughts and appreciate if you can help fixing this. I would be glad to provide more info if I have missed any.

Thanks!
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/778702#778702]

Start a new discussion in JBoss Cache at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2052]

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/jboss-user/attachments/20121127/2a066c77/attachment-0001.html

More information about the jboss-user mailing list