[infinispan-issues] [JBoss JIRA] (ISPN-2836) Thread deadlock in Map/Reduce with 2 nodes

[ https://issues.jboss.org/browse/ISPN-2836?page=com.atlassian.jira.plugin.... ] Alan Field commented on ISPN-2836: ---------------------------------- OK, I am running the job again in Jenkins using the TCP configuration. (https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/afield-radargun-mapr...) It is not generating a deadlock, but the Map/Reduce job with two nodes does not complete. With one node executing the job, I see this sequence of log messages: (From https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/afield-radargun-mapr...) {noformat} 11:09:54,934 INFO [org.radargun.Slave] (pool-1-thread-1) Executing stage: MapReduce {collatorFqn=null, exitBenchmarkOnSlaveFailure=false, mapperFqn=org.infinispan.demo.mapreduce.WordCountMapper, reducerFqn=org.infinispan.demo.mapreduce.WordCountReducer, runOnAllSlaves=false, slaves=null, useSmartClassLoading=true } 11:09:54,935 INFO [org.radargun.stages.MapReduceStage] (pool-1-thread-1) -------------------- 11:09:54,944 INFO [org.radargun.utils.ClassLoadHelper] (pool-1-thread-1) Creating newInstance org.infinispan.demo.mapreduce.WordCountMapper with classloader java.net.URLClassLoader@4bf54c5f 11:09:54,948 INFO [org.radargun.utils.ClassLoadHelper] (pool-1-thread-1) Creating newInstance org.infinispan.demo.mapreduce.WordCountReducer with classloader java.net.URLClassLoader@4bf54c5f 11:09:55,188 DEBUG [org.infinispan.distexec.mapreduce.MapReduceTask] (transport-thread-0) Invoking MapCombineCommand [keys=[], taskId=4d6ddf79-d919-4db6-ae34-20a25a158434] locally 11:11:10,174 DEBUG [org.infinispan.distexec.mapreduce.MapReduceTask] (transport-thread-0) Invoked MapCombineCommand [keys=[], taskId=4d6ddf79-d919-4db6-ae34-20a25a158434] locally 11:11:47,849 INFO [org.radargun.stages.MapReduceStage] (pool-1-thread-1) MapReduce task completed in 112.91 seconds {noformat} The RadarGun stage starts. It instantiates the Mapper and Reducer class, then the task completes after MapCombineCommand is invoked. When two nodes are executing the Map/Reduce job, an exception occurs after MapCombineCommand is invoked on the second node in the cluster. The "MapReduce task completed" from the RadarGun stage does not appear. {noformat} 11:12:45,617 INFO [org.radargun.Slave] (pool-1-thread-1) Executing stage: MapReduce {collatorFqn=null, exitBenchmarkOnSlaveFailure=false, mapperFqn=org.infinispan.demo.mapreduce.WordCountMapper, reducerFqn=org.infinispan.demo.mapreduce.WordCountReducer, runOnAllSlaves=false, slaves=null, useSmartClassLoading=true } 11:12:45,618 INFO [org.radargun.stages.MapReduceStage] (pool-1-thread-1) -------------------- 11:12:45,618 INFO [org.radargun.utils.ClassLoadHelper] (pool-1-thread-1) Creating newInstance org.infinispan.demo.mapreduce.WordCountMapper with classloader java.net.URLClassLoader@4bf54c5f 11:12:45,618 INFO [org.radargun.utils.ClassLoadHelper] (pool-1-thread-1) Creating newInstance org.infinispan.demo.mapreduce.WordCountReducer with classloader java.net.URLClassLoader@4bf54c5f 11:12:45,622 DEBUG [org.infinispan.distexec.mapreduce.MapReduceTask] (transport-thread-5) Invoking MapCombineCommand [keys=[], taskId=262e0a68-ee5c-4534-8458-97340158b129] locally 11:12:45,622 DEBUG [org.infinispan.distexec.mapreduce.MapReduceTask] (pool-1-thread-1) Invoking MapCombineCommand [keys=[], taskId=262e0a68-ee5c-4534-8458-97340158b129] on edg-perf02-43110 11:12:45,625 DEBUG [org.infinispan.distexec.mapreduce.MapReduceTask] (pool-1-thread-1) Invoked MapCombineCommand [keys=[], taskId=262e0a68-ee5c-4534-8458-97340158b129] on edg-perf02-43110 11:12:46,228 DEBUG [org.jgroups.protocols.FD] (Timer-4,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:12:49,230 DEBUG [org.jgroups.protocols.FD] (Timer-2,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:12:52,232 DEBUG [org.jgroups.protocols.FD] (Timer-2,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:12:55,233 DEBUG [org.jgroups.protocols.FD] (Timer-4,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:12:58,233 DEBUG [org.jgroups.protocols.FD] (Timer-3,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:01,235 DEBUG [org.jgroups.protocols.FD] (Timer-2,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:04,237 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:07,237 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:10,238 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:13,963 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:13,964 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) heartbeat missing from edg-perf02-43110 (number=0) 11:13:16,965 DEBUG [org.jgroups.protocols.FD] (Timer-3,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:19,966 DEBUG [org.jgroups.protocols.FD] (Timer-4,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:22,289 DEBUG [org.infinispan.distexec.mapreduce.MapReduceTask] (transport-thread-5) Invoked MapCombineCommand [keys=[], taskId=262e0a68-ee5c-4534-8458-97340158b129] locally 11:13:22,966 DEBUG [org.jgroups.protocols.FD] (Timer-4,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:25,967 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:28,969 DEBUG [org.jgroups.protocols.FD] (Timer-5,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:13:31,970 DEBUG [org.jgroups.protocols.FD] (Timer-4,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) 11:15:03,446 DEBUG [org.jgroups.protocols.FD] (Timer-4,default,edg-perf01-54809) sending are-you-alive msg to edg-perf02-43110 (own address=edg-perf01-54809) Exception in thread "main" java.util.concurrent.ExecutionException: org.infinispan.CacheException: java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to edg-perf02-43110 at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:232) at java.util.concurrent.FutureTask.get(FutureTask.java:91) at org.radargun.Slave.startCommunicationWithMaster(Slave.java:124) at org.radargun.Slave.start(Slave.java:67) at org.radargun.Slave.main(Slave.java:230) Caused by: org.infinispan.CacheException: java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to edg-perf02-43110 at org.infinispan.distexec.mapreduce.MapReduceTask.execute(MapReduceTask.java:352) at org.radargun.cachewrappers.InfinispanMapReduceWrapper.executeMapReduceTask(InfinispanMapReduceWrapper.java:98) at org.radargun.stages.MapReduceStage.executeOnSlave(MapReduceStage.java:74) at org.radargun.Slave$2.run(Slave.java:103) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) 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) Caused by: java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to edg-perf02-43110 at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222) at java.util.concurrent.FutureTask.get(FutureTask.java:83) at org.infinispan.distexec.mapreduce.MapReduceTask$TaskPart.get(MapReduceTask.java:829) at org.infinispan.distexec.mapreduce.MapReduceTask.executeMapPhaseWithLocalReduction(MapReduceTask.java:474) at org.infinispan.distexec.mapreduce.MapReduceTask.execute(MapReduceTask.java:350) ... 9 more Caused by: org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to edg-perf02-43110 at org.infinispan.util.Util.rewrapAsCacheException(Util.java:532) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:185) at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:515) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:180) 11:15:03,459 WARN [org.jgroups.protocols.FD] (OOB-90,default,edg-perf01-54809) I was suspected by edg-perf02-43110; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:202) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:259) at org.infinispan.remoting.rpc.RpcManagerImpl.access$000(RpcManagerImpl.java:82) at org.infinispan.remoting.rpc.RpcManagerImpl$1.call(RpcManagerImpl.java:293) ... 5 more Caused by: org.jgroups.TimeoutException: timeout sending message to edg-perf02-43110 at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:390) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:299) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:178) ... 11 more {noformat} After this exception occurs, a number of message sends fail, then a MERGE event and a VIEW_CHANGE occur. After this point, the two nodes send a stream of "are-you-alive" messages to each other, and the RadarGun stage never completes. Jenkins eventually kills the job. I will run this job again using the UDP configuration, but I think the behavior will be the same, since the org.jgroups.TimeoutException is also seen above. -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira