0 Replies Latest reply on Nov 27, 2012 4:31 PM by Vikram Murugesan

    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 Newbie

      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 [/prefix/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 [/prefix/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@e97df0 Drive beforeCompletion participants.

      org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/prefix/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!