Re: [jbosscache-dev] LockParentForChildInsertRemove and PessimisticLocking

Another detail that may or may not be relevant: Note that the failed lock attempt msg is for a "upgrade lock" not a "write lock". That indicates IdentityLock already had the caller thread listed as a RL owner on the node. Not sure why the thread would have a RL on the node.

Brian Stansberry wrote: > Sorry, nope. :( > I might (30% chance) be able to create one later today. > Manik Surtani wrote: >> You wouldn't have this encapsulated as a unit test, would you? >> >> On 5 Aug 2009, at 14:42, Brian Stansberry wrote: >> >>> Paul and I have been poking through code trying to diagnose the >>> issue >>> that led to this thread for quite a while yesterday. Time to >>> throw it >>> out there and see if anyone hopefully spots something: >>> >>> This is web session replication with buddy replication. The >>> "LockParentForChildInsertRemove" property isn't configured on the >>> cache, >>> so the default "false" should be in effect. A thread trying to >>> execute a >>> remote DataGravitationCleanupCommand on a session node fails >>> upgrading >>> to a write lock on fqn /BUDDY_MANAGER.[1] We can't understand why >>> it >>> would want a WL. >>> >>> Looking at the PessimisticNodeBasedLockManager code, the only >>> reasons I >>> see why a WL would be requested here are: >>> >>> 1) The invocation created the previously non-existent / >>> BUDDY_MANAGER >>> node in order to execute the remove of the >>> great-great-great-great-grandchild. Highly unlikely in general and >>> logging shows another thread successfully doing a put on a >>> different >>> great-great-great-great-grandchild a millisecond earlier. (Also >>> other >>> test runs w/ less verbose logging showed failures getting a WL on >>> fqn / >>> which of course exists). >>> >>> 2) In call to PNBLM.writeLockNeeded(...) >>> currentNode.isLockForChildInsertRemove() is returning "true". Which >>> AFAICT it shouldn't be. >>> >>> [1] The logging from the thread: >>> >>> [JBoss] 20:29:27,488 TRACE >>> [org.jboss.cache.marshall.CommandAwareRpcDispatcher] >>> (Incoming-5,10.34.32.154:46064) Executing command: >>> DataGravitationCleanupCommand{fqn=/JSESSION/st_localhost/ >>> wUaU4FhUzWcuiDEjkJzDiQ__, >>> backup=/_BUDDY_BACKUP_/10.34.32.155_41754:DEAD/1/JSESSION/ >>> st_localhost/wUaU4FhUzWcuiDEjkJzDiQ__} >>> [sender=10.34.32.153:24595] >>> [JBoss] 20:29:27,489 TRACE >>> [org.jboss.cache.marshall.CommandAwareRpcDispatcher] >>> (Incoming-5,10.34.32.154:46064) This is a non-visitable command - >>> so >>> performing directly and not via the invoker. >>> [JBoss] 20:29:42,497 ERROR >>> [org.jboss.cache.lock.ReadWriteLockWithUpgrade] >>> (Incoming-5,10.34.32.154:46064) upgradeLock(): failed >>> [JBoss] 20:29:42,500 TRACE >>> [org.jboss.cache.marshall.CommandAwareRpcDispatcher] >>> (Incoming-5,10.34.32.154:46064) Problems invoking command. >>> [JBoss] org.jboss.cache.lock.UpgradeException: upgrade lock for >>> /_BUDDY_BACKUP_ could not be acquired after 15000 ms. Lock map >>> ownership >>> Read lock owners: [GlobalTransaction:<10.34.32.153:24595>:70, >>> GlobalTransaction:<10.34.32.153:24595>:69] >>> [JBoss] Write lock owner: null >>> [JBoss] (caller=Thread[Incoming-5,10.34.32.154:46064,5,Thread >>> Pools], >>> lock info: read owners=[GlobalTransaction:<10.34.32.153:24595>: >>> 70, >>> GlobalTransaction:<10.34.32.153:24595>:69] (activeReaders=2, >>> activeWriter=null, waitingReaders=1, waitingWriters=0, >>> waitingUpgrader=0)) >>> [JBoss] at >>> org >>> .jboss >>> .cache.lock.IdentityLock.acquireWriteLock0(IdentityLock.java:227) >>> [JBoss] at >>> org >>> .jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java: >>> 176) >>> [JBoss] at >>> org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:503) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .lock >>> .PessimisticNodeBasedLockManager >>> .acquireNodeLock(PessimisticNodeBasedLockManager.java:260) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .lock >>> .PessimisticNodeBasedLockManager >>> .lock(PessimisticNodeBasedLockManager.java:169) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .lock >>> .PessimisticNodeBasedLockManager >>> .lockPessimistically(PessimisticNodeBasedLockManager.java:97) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .PessimisticLockInterceptor >>> .handleRemoveNodeCommand(PessimisticLockInterceptor.java:265) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base >>> .PrePostProcessingCommandInterceptor >>> .visitRemoveNodeCommand(PrePostProcessingCommandInterceptor.java: >>> 126) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base >>> .CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java: >>> 116) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .ReplicationInterceptor >>> .handleCrudMethod(ReplicationInterceptor.java:148) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .ReplicationInterceptor >>> .visitRemoveNodeCommand(ReplicationInterceptor.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base >>> .CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java: >>> 116) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base.CommandInterceptor.handleDefault(CommandInterceptor.java:131) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base >>> .CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java: >>> 116) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .TxInterceptor.attachGtxAndPassUpChain(TxInterceptor.java:301) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors.TxInterceptor.handleDefault(TxInterceptor.java:283) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base >>> .CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java: >>> 116) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base.CommandInterceptor.handleDefault(CommandInterceptor.java:131) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .base >>> .CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java: >>> 116) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .InvocationContextInterceptor >>> .handleAll(InvocationContextInterceptor.java:178) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .interceptors >>> .InvocationContextInterceptor >>> .visitRemoveNodeCommand(InvocationContextInterceptor.java:88) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125) >>> [JBoss] at >>> org >>> .jboss >>> .cache.interceptors.InterceptorChain.invoke(InterceptorChain.java: >>> 287) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .remote >>> .DataGravitationCleanupCommand >>> .executeRemove(DataGravitationCleanupCommand.java:151) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .commands >>> .remote >>> .DataGravitationCleanupCommand >>> .perform(DataGravitationCleanupCommand.java:105) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .marshall >>> .CommandAwareRpcDispatcher >>> .executeCommand(CommandAwareRpcDispatcher.java:305) >>> [JBoss] at >>> org >>> .jboss >>> .cache >>> .marshall >>> .CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java: >>> 242) >>> [JBoss] at >>> org >>> .jgroups >>> .blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) >>> [JBoss] at >>> org >>> .jgroups >>> .blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java: >>> 545) >>> [JBoss] at >>> org >>> .jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java: >>> 368) >>> [JBoss] at >>> org.jgroups.blocks.MessageDispatcher >>> $ProtocolAdapter.up(MessageDispatcher.java:775) >>> [JBoss] at org.jgroups.JChannel.up(JChannel.java:1339) >>> [JBoss] at >>> org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:462) >>> [JBoss] at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java: >>> 432) >>> [JBoss] at >>> org >>> .jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java: >>> 144) >>> [JBoss] at org.jgroups.protocols.FRAG2.up(FRAG2.java:188) >>> [JBoss] at org.jgroups.protocols.FC.up(FC.java:473) >>> [JBoss] at org.jgroups.protocols.pbcast.GMS.up(GMS.java:824) >>> [JBoss] at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java: >>> 233) >>> [JBoss] at >>> org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:616) >>> [JBoss] at org.jgroups.protocols.UNICAST.up(UNICAST.java:282) >>> [JBoss] at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java: >>> 758) >>> [JBoss] at >>> org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167) >>> [JBoss] at org.jgroups.protocols.FD.up(FD.java:284) >>> [JBoss] at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:309) >>> [JBoss] at org.jgroups.protocols.MERGE2.up(MERGE2.java:144) >>> [JBoss] at org.jgroups.protocols.Discovery.up(Discovery.java: >>> 264) >>> [JBoss] at org.jgroups.protocols.PING.up(PING.java:273) >>> [JBoss] at org.jgroups.protocols.TP >>> $ProtocolAdapter.up(TP.java:2327) >>> [JBoss] at org.jgroups.protocols.TP.passMessageUp(TP.java:1261) >>> [JBoss] at org.jgroups.protocols.TP.access$100(TP.java:49) >>> [JBoss] at >>> org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java: >>> 1838) >>> [JBoss] at org.jgroups.protocols.TP >>> $IncomingPacket.run(TP.java:1817) >>> [JBoss] at >>> java.util.concurrent.ThreadPoolExecutor >>> $Worker.runTask(ThreadPoolExecutor.java:886) >>> [JBoss] at >>> java.util.concurrent.ThreadPoolExecutor >>> $Worker.run(ThreadPoolExecutor.java:908) >>> [JBoss] at java.lang.Thread.run(Thread.java:619) >>> >>> Manik Surtani wrote: >>>> On 4 Aug 2009, at 21:28, Brian Stansberry wrote: >>>> >>>>> Continuing dialogue with myself. :) >>>>> >>>>> I've found the logic in PessimisticNodeBasedLockManager where the >>>>> LockParentForChildInsertRemove configuration is meant to be >>>>> coming >>>>> through via the Node. >>>> Yes, this is because you can override this on a per-node basis. >>>> >>>>> In our testing we're seeing cases where write >>>>> locks are being acquired on parent nodes, which isn't the >>>>> intent. I'll >>>>> dig further. >>>>> >>>>> Brian Stansberry wrote: >>>>>> https://jira.jboss.org/jira/browse/JBCACHE-1527 >>>>>> >>>>>> Brian Stansberry wrote: >>>>>>> From looking at the JBC 3 code, it seems the >>>>>>> LockParentForChildInsertRemove configuration is no longer >>>>>>> respected for >>>>>>> pessimistic locking. I can't trace any path from the >>>>>>> property in >>>>>>> Configuration to code that uses it. >>>>>>> PessimisticLockInterceptor.handlePutCommand, >>>>>>> handleMoveCommand and >>>>>>> handleRemoveNodeCommand all always tell the lock manager to >>>>>>> lock >>>>>>> parents. handleEvictFqnCommand always tells the lock manager >>>>>>> not to >>>>>>> lock >>>>>>> parents. >>>>>>> >>>>>>> This is causing failures in buddy replication testing when >>>>>>> nodes >>>>>>> join/leave clusters under load. There's a lot of data >>>>>>> gravitation plus >>>>>>> stuff like migrating defunct backup trees to "DEAD" regions. >>>>>>> Too much >>>>>>> contention for parent level locks. >>>>>>> >>>>>>> Plus locking on the structural parent to add/remove session >>>>>>> nodes will >>>>>>> suck for the session caching use case. >>>>>>> >>>>>> >>>>> >>>>> -- >>>>> Brian Stansberry >>>>> Lead, AS Clustering >>>>> JBoss by Red Hat >>>>> _______________________________________________ >>>>> jbosscache-dev mailing list >>>>> jbosscache-dev(a)lists.jboss.org >>>>> https://lists.jboss.org/mailman/listinfo/jbosscache-dev >>>> -- >>>> Manik Surtani >>>> manik(a)jboss.org >>>> Lead, Infinispan >>>> Lead, JBoss Cache >>>> http://www.infinispan.org >>>> http://www.jbosscache.org >>>> >>>> >>>> >>>> >>> >>> -- >>> Brian Stansberry >>> Lead, AS Clustering >>> JBoss by Red Hat >>> _______________________________________________ >>> jbosscache-dev mailing list >>> jbosscache-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/jbosscache-dev >> -- >> Manik Surtani >> manik(a)jboss.org >> Lead, Infinispan >> Lead, JBoss Cache >> http://www.infinispan.org >> http://www.jbosscache.org >> >> >> >> -- Brian Stansberry Lead, AS Clustering JBoss by Red Hat