[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Manik Surtani reassigned ISPN-1602: ----------------------------------- Assignee: Dan Berindei (was: Manik Surtani) -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Bela Ban commented on ISPN-1602: -------------------------------- Erik, what do you mean by "JGroups 3.x is dropping views" ? Also, you mention "dropped messages", what do you mean by that ? I assume this is relevant to our discussion via IRC and email yesterday ? Please clarify the above 2 statements, so I can take a look. Cheers, -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Bela Ban commented on ISPN-1602: -------------------------------- Dan, RECOVER_VIEW might benefit from marking it as RSVP [1] at some point when you guys use JGroups 3.1... We should have a meeting some time to discuss where RSVP marked messages might make sense. [1] http://belaban.blogspot.com/2011/12/repondez-sil-vous-plait.html -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Bela Ban commented on ISPN-1602: -------------------------------- grep "GMS: address" *.log | grep erm-cluster shows that you have - dht10 and dht13 with suffix site01, - dht11 and dht14 with suffix site02, - dht12 and dht15 with suffix site03 Does this indicate that you set up site replication using RELAY ? Didn't see RELAY though in the config you sent me yesterday... Or do you only use an AddressGenerator to generates instances of PayloadUUIDs ? -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Dan Berindei commented on ISPN-1602: ------------------------------------ Some more clarifications from Erik: * The test doesn't use RELAY, it only uses Infinispan's TopologyAwareConsistentHash, which adds topology information to the JGroups addresses. * The heap size is 6GB, but the perf test only uses ~ 2GB. So there is no Full GC during the whole test run that could explain the FD failures. -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Dan Berindei commented on ISPN-1602: ------------------------------------ Erik I've been looking in the logs for stale locks but I couldn't find any key that was never released. I did find a lot of errors acquiring locks, but nothing unusual. Then I looked at the duration of cache view installations. Most took well below 1 second, a few took ~ 10 seconds (because they had to wait for a LockControlCommand to time out), and one took > 60 seconds: {noformat} 2011-12-08 21:46:17,629 DEBUG [org.infinispan.cacheviews.CacheViewsManagerImpl] (CacheViewInstaller-4,dht10-14621(site01)) Installing new view CacheView{viewId=7, members=[dht10-14621(site01), dht12-11638(site03), dht14-60002(site02)]} for cache serviceGroup 2011-12-08 21:47:36,938 DEBUG [org.infinispan.cacheviews.CacheViewsManagerImpl] (CacheViewInstaller-4,dht10-14621(site01)) serviceGroup: Committing cache view 7 {noformat} Most of that time seems to spent between node {{dht10-14621}} sending the {{COMMIT_VIEW}} command and node {{dht14-60002}} executing the command: {noformat} server-dht10.log:2011-12-08 21:46:46,863 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (CacheViewInstaller-4,dht10-14621(site01)) Replication task sending CacheViewControlCommand{cache=serviceGroup, type=COMMIT_VIEW, sender=dht10-14621(site01), newViewId=7, newMembers=null, oldViewId=0, oldMembers=null} to addresses [dht10-14621(site01), dht12-11638(site03), dht14-60002(site02)] server-dht12.log:2011-12-08 21:46:46,858 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-71,erm-cluster-0a0a0e3c,dht12-11638(site03)) Attempting to execute command: CacheViewControlCommand{cache=serviceGroup, type=COMMIT_VIEW, sender=dht10-14621(site01), newViewId=7, newMembers=null, oldViewId=0, oldMembers=null} [sender=dht10-14621(site01)] server-dht14.log:2011-12-08 21:47:36,932 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-118,erm-cluster-0a0a0e3c,dht14-60002(site02)) Attempting to execute command: CacheViewControlCommand{cache=serviceGroup, type=COMMIT_VIEW, sender=dht10-14621(site01), newViewId=7, newMembers=null, oldViewId=0, oldMembers=null} [sender=dht10-14621(site01)] {noformat} I didn't see any JGroups warnings about dropped messages from {{dht10-14621}}, so I'm guessing the OOB thread pool is full. Make sure you don't have {{oob_thread_pool.queue_enabled="true"}} in your config, or you'll only use {{oob_thread_pool.min_threads}} most of the time. -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Erik Salter edited comment on ISPN-1602 at 12/13/11 4:06 PM: ------------------------------------------------------------- Here's the TCP version of the 3.0.1 config I WAS using. (This was also a thread on the jgroups-users list) was (Author: an1310): Here's the TCP version of the 3.0.1 config. (This was also a thread on the jgroups-users list) -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Dan Berindei commented on ISPN-1602: ------------------------------------ I got a similar situation in the test suite, but with 2 view changes: {noformat} Initial cluster view is A2 [A, B] tx_A: sends CommitCommand cc to B C: sends REQUEST_JOIN A: sends PREPARE_VIEW(3, [A, B, C]) to B, C A: blocks write commands for cache view 3 B: blocks write commands for cache view 3 tx_B: rejects cc with a StateTransferInProgress tx_A: waits for state transfer 3 to end A: sends COMMIT_VIEW(3) to B, C A: unblocks transactions tx_A: resends cc to B tx_B: rejects cc again, because state transfer hasn't ended on B yet tx_A: waits for state transfer 3 to end but since state transfer 3 has already ended on A, it doesn't actually wait at all tx_A: resends cc to B tx_B: rejects cc the 3rd time B: finally receives the COMMIT_VIEW(3) command and unblocks transactions, but it's too late for cc {noformat} My pull req for ISPN-1581 will fix this because it will retry commands for much longer (indefinitely for commit commands). There will be some extra StateTransferInProgressExceptions in the log, but that's about it. -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Erik Salter commented on ISPN-1602: ----------------------------------- Here's some logs after incorporating the pull request: http://dl.dropbox.com/u/50401510/5.1.0.CR2/failed_rehash.tgz -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Dan Berindei edited comment on ISPN-1602 at 12/16/11 2:50 AM: -------------------------------------------------------------- I looked at the new logs and the issue seems to be at the transport level again: {noformat} 2011-12-15 21:34:23,883 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (transport-thread-60) Replication task sending CacheViewControlCommand{cache=serviceGroup, type=PREPARE_VIEW, sender=dht11-10896(site02), newViewId=7, newMembers=[dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01), dht15-26478(site03)], oldViewId=6, oldMembers=[dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01)]} to addresses [dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01), dht15-26478(site03)] 2011-12-15 21:34:23,883 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (transport-thread-60) real_dests=[dht12-30558(site03), dht14-32511(site02), dht13-53236(site01), dht15-26478(site03)] 2011-12-15 21:35:50,836 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-247,erm-cluster-0a0a0e3c,dht14-32511(site02)) Attempting to execute command: CacheViewControlCommand{cache=serviceGroup, type=PREPARE_VIEW, sender=dht11-10896(site02), newViewId=7, newMembers=[dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01), dht15-26478(site03)], oldViewId=6, oldMembers=[dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01)]} [sender=dht11-10896(site02)] {noformat} Can you change the JGroups config so that {{STABLE.desired_avg_gossip}} < {{rehashRpcTimeout}} and give it another try? was (Author: dan.berindei): I looked at the new logs and the issue seems to be at the transport level again: {noformat} 2011-12-15 21:34:23,883 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (transport-thread-60) real_dests=[dht12-30558(site03), dht14-32511(site02), dht13-53236(site01), dht15-26478(site03)] 2011-12-15 21:35:50,836 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-247,erm-cluster-0a0a0e3c,dht14-32511(site02)) Attempting to execute command: CacheViewControlCommand{cache=serviceGroup, type=PREPARE_VIEW, sender=dht11-10896(site02), newViewId=7, newMembers=[dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01), dht15-26478(site03)], oldViewId=6, oldMembers=[dht11-10896(site02), dht12-30558(site03), dht14-32511(site02), dht13-53236(site01)]} [sender=dht11-10896(site02)] {noformat} Can you change the JGroups config so that {{STABLE.desired_avg_gossip}} < {{rehashRpcTimeout}} and give it another try? -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Erik Salter edited comment on ISPN-1602 at 12/19/11 3:08 PM: ------------------------------------------------------------- Now there are lock timeouts with a stable cluster (no rehash) with ISPN-1584 applied. http://dl.dropbox.com/u/50401510/5.1.0.CR2/200threads-withoutrehash.7z (I apologize in advance for the size of this file.) A good place to start is ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144] on dht14. This test is with 200 threads accessing 252 keys. The only thing interesting about this cache is that it's simply an aggregator. No data is being stored in this cache. For reference, there is another cache (SopSegment) that has these 200 threads accessing 4 keys without issue. was (Author: an1310): Now there are lock timeouts with a stable cluster (no rehash) http://dl.dropbox.com/u/50401510/5.1.0.CR2/200threads-withoutrehash.7z (I apologize in advance for the size of this file.) A good place to start is ServiceGroupKey[edgeDeviceId=45,serviceGroupNo=144] on dht14. This test is with 200 threads accessing 252 keys. The only thing interesting about this cache is that it's simply an aggregator. No data is being stored in this cache. For reference, there is another cache (SopSegment) that has these 200 threads accessing 4 keys without issue. -- 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

[ 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Galder Zamarreño updated ISPN-1602: ----------------------------------- Fix Version/s: 5.1.0.FINAL (was: 5.1.0.CR3) -- 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

[ https://issues.jboss.org/browse/ISPN-1602?page=com.atlassian.jira.plugin.... ] Galder Zamarreño updated ISPN-1602: ----------------------------------- Fix Version/s: (was: 5.1.0.FINAL) -- 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