Begin forwarded message:
> From: Guillaume Laforge <[email protected]> > Subject: Re: [gradle-user] Build hanging at test execution > Date: 15 November 2011 10:02:19 PM GMT > To: [email protected] > Reply-To: [email protected] > > Hi Adam, > > So with milestone 5, I just did a kill -3 on the two Gradle processes that I > was seeing running with ps aux on my Mac, and here's what I get, below. > I see no trace of my own code there (Gaelyk), nor of the library I'm using > (the Google App Engine SDK), and only see Gradle stuff :-( After looking through the stacks, my only conclusion is that the worker process never received the stop method call. A couple of interesting parts: > "socket connection at /0:0:0:0:0:0:0:1%0:51890 with /0:0:0:0:0:0:0:1:51874 > receive" prio=5 tid=1018d6000 nid=0x109e4a000 runnable [109e48000] > java.lang.Thread.State: RUNNABLE > at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) > at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136) > at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69) > at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) > - locked <7f45905c0> (a sun.nio.ch.Util$2) > - locked <7f45905a8> (a java.util.Collections$UnmodifiableSet) > - locked <7f44e1ce8> (a sun.nio.ch.KQueueSelectorImpl) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84) > at > org.gradle.messaging.remote.internal.inet.SocketConnection$SocketInputStream.read(SocketConnection.java:142) > at java.io.DataInputStream.read(DataInputStream.java:132) > at > java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2265) > at > java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2278) > at > java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:2749) > at > java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:779) > at java.io.ObjectInputStream.<init>(ObjectInputStream.java:279) > at > org.gradle.util.ClassLoaderObjectInputStream.<init>(ClassLoaderObjectInputStream.java:27) > at > org.gradle.messaging.remote.internal.Message$ExceptionReplacingObjectInputStream.<init>(Message.java:151) > at org.gradle.messaging.remote.internal.Message.receive(Message.java:37) > at > org.gradle.messaging.remote.internal.DefaultMessageSerializer.read(DefaultMessageSerializer.java:31) > at > org.gradle.messaging.remote.internal.inet.SocketConnection.receive(SocketConnection.java:75) > at > org.gradle.messaging.remote.internal.DelegatingConnection.receive(DelegatingConnection.java:31) > at > org.gradle.messaging.remote.internal.MessageHub$EeamConnection.receive(MessageHub.java:210) > at > org.gradle.messaging.remote.internal.MessageHub$EndOfStreamConnection.receive(MessageHub.java:195) > at > org.gradle.messaging.remote.internal.AsyncConnectionAdapter$ConnectionReceive.receive(AsyncConnectionAdapter.java:77) > at > org.gradle.messaging.dispatch.AsyncReceive.receiveMessages(AsyncReceive.java:125) > at > org.gradle.messaging.dispatch.AsyncReceive.access$000(AsyncReceive.java:32) > at > org.gradle.messaging.dispatch.AsyncReceive$1.run(AsyncReceive.java:74) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > 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:680) [worker process] - this looks like the message consumer thread, blocked in a read > "main" prio=5 tid=101801800 nid=0x100501000 waiting on condition [100500000] > java.lang.Thread.State: WAITING (parking) > at sun.misc.Unsafe.park(Native Method) > - parking to wait for <7f4572288> (a > java.util.concurrent.CountDownLatch$Sync) > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281) > at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207) > at > org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:74) > at > org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:35) > at > org.gradle.process.internal.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:77) > at > org.gradle.process.internal.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:35) > at > org.gradle..internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:79) > at > org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:35) > at > org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:56) > at > org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:38) > at > org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:52) > at > org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:33) > at > org.gradle.process.internal.launcher.GradleWorkerMain.run(GradleWorkerMain.java:30) > at > org.gradle.process.internal.launcher.GradleWorkerMain.main(GradleWorkerMain.java:35) [worker process] - this is the “main” thread, it's waiting on a latch that gets triggered when the worker process sees message to stop. Now for the other side… > "socket connection at /0:0:0:0:0:0:0:1%0:51874 with /0:0:0:0:0:0:0:1%0:51890 > receive" prio=5 tid=101adf000 nid=0x10b3fc000 runnable [10b3fa000] > java.lang.Thread.State: RUNNABLE > at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) > at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136) > at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69) > at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) > - locked <7f3ad4598> (a sun.nio.ch.Util$2) > - locked <7f3ad4588> (a java.util.Collections$UnmodifiableSet) > - locked <7f3ad4380> (a sun.nio.ch.KQueueSelectorImpl) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84) > at > org.gradle.messaging.remote.internal.inet.SocketConnection$SocketInputStream.read(SocketConnection.java:142) > at java.io.DataInputStream.read(DataInputStream.java:132) > at > java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2265) > at > java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2278) > at > java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:2749) > at > java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:779) > at java.io.ObjectInputStream.<init>(ObjectInputStream.java:279) > at > org.gradle.util.ClassLoaderObjectInputStream.<init>(ClassLoaderObjectInputStream.java:27) > at > org.gradle.messaging.remote.internal.Message$ExceptionReplacingObjectInputStream.<init>(Message.java:151) > at org.gradle.messaging.remote.internal.Message.receive(Message.java:37) > at > org.gradle.messaging.remote.internal.DefaultMessageSerializer.read(DefaultMessageSerializer.java:31) > at > org.gradle.messaging.remote.internal.inet.SocketConnection.receive(SocketConnection.java:75) > at > org.gradle.messaging.remote.internal.DelegatingConnection.receive(DelegatingConnection.java:31) > at > org.gradle.messaging.remote.internal.MessageHub$EndOfStreamConnection.receive(MessageHub.java:210) > at > org.gradle.messaging.remote.internal.MessageHub$EndOfStreamConnection.receive(MessageHub.java:195) > at > org.gradle.messaging.remote.internal.AsyncConnectionAdapter$ConnectionReceive.receive(AsyncConnectionAdapter.java:77) > at > org.gradle.messaging.dispatch.AsyncReceive.receiveMessages(AsyncReceive.java:125) > at > org.gradle.messaging.dispatch.AsyncReceive.access$000(AsyncReceive.java:32) > at > org.gradle.messaging.dispatch.AsyncReceive$1.run(AsyncReceive.java:74) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > 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:680) [build process] - looks like the read side of the connection to the worker, blocked in a read > "Run Gradle Worker 1 Thread 4" prio=5 tid=101acc000 nid=0x10b2f9000 runnable > [10b2f8000] > java.lang.Thread.State: RUNNABLE > at java.io.FileInputStream.readBytes(Native Method) > at java.io.FileInputStream.read(FileInputStream.java:198) > at > java.lang.UNIXProcess$DeferredCloseInputStream.read(UNIXProcess.java:218) > at > org.gradle.process.internal.ExecOutputHandleRunner.run(ExecOutputHandleRunner.java:46) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > 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:680) [build process] - unsure what this is > "Run Gradle Worker 1 Thread 3" prio=5 tid=101acb000 nid=0x10b19c000 runnable > [10b19b000] > java.lang.Thread.State: RUNNABLE > at java.io.FileInputStream.readBytes(Native Method) > at java.io.FileInputStream.read(FileInputStream.java:220) > at > java.lang.UNIXProcess$DeferredCloseInputStream.read(UNIXProcess.java:227) > at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) > at java.io.BufferedInputStream.read1(BufferedInputStream.java:258) > at java.io.BufferedInputStream.read(BufferedInputStream.java:317) > - locked <7f30e37f8> (a java.io.BufferedInputStream) > at java.io.FilterInputStream.read(FilterInputStream.java:90) > at > org.gradle.process.internal.ExecOutputHandleRunner.run(ExecOutputHandleRunner.java:46) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > 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:680) [build process] - unsure about this one too > "Run Gradle Worker 1 Thread 2" prio=5 tid=101ac8000 nid=0x10a8bd000 in > Object.wait() [10a8bc000] > java.lang.Thread.State: WAITING (on object monitor) > at java.lang.Object.wait(Native Method) > - waiting on <7f30e1278> (a java.lang.UNIXProcess) > at java.lang.Object.wait(Object.java:485) > at java.lang.UNIXProcess.waitFor(UNIXProcess.java:115) > - locked <7f30e1278> (a java.lang.UNIXProcess) > at > org.gradle.process.internal.ExecHandleRunner.run(ExecHandleRunner.java:88) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > 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:680) [build process] - this must be our handle on the worker process > "Dispatch > org.gradle.api.internal.tasks.testing.processors.RestartEveryNTestClassProcessor@49dc11af" > prio=5 tid=101ab7000 nid=0x109a8d000 waiting on condition [109a8b000] > java.lang.Thread.State: TIMED_WAITING (parking) > at sun.misc.Unsafe.park(Native Method) > - parking to wait for <7f42b39d0> (a > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) > at > java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025) > at > java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1253) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl.stop(DefaultExecutorFactory.java:89) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl.stop(DefaultExecutorFactory.java:79) > at > org.gradle.process.internal.DefaultExecHandle.waitForFinish(DefaultExecHandle.java:274) > at > org.gradle.process.internal.DefaultWorkerProcess.waitForStop(DefaultWorkerProcess.java:132) > at > org.gradle.api.internal.tasks.testing.worker.ForkingTestClassProcessor.stop(ForkingTestClassProcessor.java:77) > at > org.gradle.api.internal.tasks.testing.processors.RestartEveryNTestClassProcessor.endBatch(RestartEveryNTestClassProcessor.java:60) > at > org.gradle.api.internal.tasks.testing.processors.RestartEveryNTestClassProcessor.stop(RestartEveryNTestClassProcessor.java:54) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) > at > org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) > at > org.gradle.messaging.dispatch.FailureHandlingDispatch.dispatch(FailureHandlingDispatch.java:29) > at > org.gradle.messaging.dispatch.AsyncDispatch.dispatchMessages(AsyncDispatch.java:132) > at > org.gradle.messaging.dispatch.AsyncDispatch.access$000(AsyncDispatch.java:33) > at > org.gradle.messaging.dispatch.AsyncDispatch$1.run(AsyncDispatch.java:72) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > 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:680) [build process] - this is the worker controller effectively. It *has* asked the worker to stop [ForkingTestClassProcessor.stop(ForkingTestClassProcessor.java:77)] which seems to have been dispatched, now it's waiting for the process to die. So the question is, where is the stop message? The build process has sent it, but there is no trace of the worker ever receiving it. This leads me to think that either it never got to the worker, or an error occurred trying to process it that prevented it from getting to the receive proxy. If the stop message made it through the messaging infrastructure, it would get to: http://github.com/gradle/gradle/tree/master/subprojects/plugins/src/main/groovy/org/gradle/api/internal/tasks/testing/worker/TestWorker.java#L89 This simply means it did not get that far. If it had, that latch would have been triggered and we wouldn't see the thread in the worker sitting and waiting on it at http://github.com/gradle/gradle/tree/master/subprojects/plugins/src/main/groovy/org/gradle/api/internal/tasks/testing/worker/TestWorker.java#L74 I think the next thing we need is debug trace for both sides. I'm unsure how to get debug trace for the worker threads though. -- Luke Daley Principal Engineer, Gradleware http://gradleware.com
