On 18/11/2011, at 8:25 PM, Guillaume Laforge <[email protected]> wrote:
> I'm still wondering if that could be something in my codebase also that could
> be influencing that strange behaviour.
> My code base has evolved since when it was failing a few days ago, and I've
> tried running again the build with gradle test, and then it wasn't hanging
> anymore.
> Perhaps going back through an older revision I could find a point where it
> was failing.
> In my tests, I'm using the unit testing classes of the Google App Engine SDK,
> which use thread locals and probably other tricks... perhaps it could be
> launching some daemon threads or something (but I'd expect to see them though
> in the traces).
> Could you think of something that a test could be doing, that could prevent
> Gradle from doing its job?
> And interesting... something that would not prevent IntelliJ from exhibiting
> the same behaviour...
Running from IntelliJ bypasses all of our messaging infrastructure, which is
almost certainly where the problem is so there is no surprise there.
I don't think your code is involved directly as, like you said, you'd expect to
see it in the stacks if it were. There ate no tests running in these stacks.
We can reproduce this outside of your project with m4 onwards, so it's not a
direct link but something about gaelyk is triggering this a lot.
I'm starting to suspect it's something stdio related for a few reasons but it's
too early to tell. Hopefully we'll know more soon.
>
> Guillaume
>
> On Fri, Nov 18, 2011 at 20:03, Luke Daley <[email protected]> wrote:
>
>
> 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
>
>
>
>
> --
> Guillaume Laforge
> Groovy Project Manager
> SpringSource, a division of VMware
>
> Blog: http://glaforge.appspot.com/
> Twitter: @glaforge
> Google+: http://gplus.to/glaforge
>
