[infinispan-issues] [JBoss JIRA] (ISPN-1602) Single view change causes stale locks

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Dan Berindei commented on ISPN-1602: ------------------------------------ Erik, I've investigated the {{ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144]}} logs and the lock is never "leaked". I did find some transactions that kept it locked ~ 1 minute, but that's because a remote get and a TxCompletionNotification took ~ 30 seconds each to start executing on the remote node: {noformat} 2011-12-16 17:19:38,935 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-136,erm-cluster-0a0a0e3c,dht14-65317(site02)) Replication task sending ClusteredGetCommand{key=ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144], flags=null} to addresses [dht12-15582(site03), dht11-11001(site02), dht10-34698(site01)] 2011-12-16 17:20:04,634 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (Incoming-7,erm-cluster-0a0a0e3c,dht12-15582(site03)) Attempting to execute command: TxCompletionNotificationCommand{ xid=null, internalId=0, gtx=GlobalTransaction:<dht14-65317(site02)>:5524:local, cacheName=eigAllocation} [sender=dht14-65317(site02)] 2011-12-16 17:20:04,744 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-136,erm-cluster-0a0a0e3c,dht14-65317(site02)) Replication task sending TxCompletionNotificationCommand{ xid=null, internalId=0, gtx=GlobalTransaction:<dht14-65317(site02)>:5065:local, cacheName=serviceGroup} to addresses [dht11-11001(site02), dht10-34698(site01), dht12-15582(site03)] 2011-12-16 17:18:46,653 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (Incoming-7,erm-cluster-0a0a0e3c,dht12-15582(site03)) Attempting to execute command: TxCompletionNotificationCommand{ xid=null, internalId=0, gtx=GlobalTransaction:<dht14-65317(site02)>:160:local, cacheName=qamAllocation} [sender=dht14-65317(site02)] {noformat} One reason might be that the non-OOB thread pool has queueing enabled, although with a queue size of 100 and only ClusteredGetCommands/TxCompletionNotifications executing on the non-OOB thread pool I don't see how one element could take > 20 seconds to reach the front of the queue. I suggest doing a shorter test run with TRACE enabled for JGroups as well as for Infinispan and taking a thread dump every 5 seconds in order to investigate this better. PS: This is how I checked for stale locks: {noformat} zcat 200threads-withoutrehash/*/server.log*.gz| grep "Failed to acquire lock" | sed -n -e 's/.*Failed to acquire lock \(.*\), owner is.*/\1/p' | sort | uniq>keys.txt for k in "ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144]" ; do zcat 200threads-withoutrehash/*/server.log*.gz | grep -F $k | egrep "Failed to acquire|Successfully acquired lock|Attempting to unlock" > tmp.txt ; tail -1 tmp.txt | grep -q "Failed to acquire" && (echo --- $k --- ; cat $tmp.txt) ; done {noformat} To see the lock acquisitions/releases for ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144]: {noformat} for k in "ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144]" ; do zcat 200threads-withoutrehash/*/server.log*.gz | grep -F $k | egrep "Failed to acquire|Successfully acquired lock|Attempting to unlock" > edgeDeviceId=45,serviceGroupNo=144.txt ; done cat edgeDeviceId=45,serviceGroupNo=144.txt | sed -n 's/\(.*\) \(DEBUG\|TRACE\) .*\(Fail\|acquired\|unlock\).*/\1 \3/p' | less {noformat} -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa For more information on JIRA, see: http://www.atlassian.com/software/jira