Hung worker/OOME running TestNG

mondrejko · February 1, 2017, 6:43pm

We are seeing an issue (using both Gradle 3.2 and Gradle 3.3) that is fairly consistent across all of our build environments (dev builds, jenkins and teamcity) where the TestNG worker process hangs or fails with an OutOfMemoryError.

The test implement uses a thirdparty library, dbunit, that may contains lots and lots of logging (when run previously, we had this debugging mostly depressed). However, I have been able to trace the root of the issues we see to these (even suppressed) log messages seemingly being sent to the Gradle main build process.

The attached jstack output is from a hung worker process. Also, note that when we encounter the OOME in this case, it does not matter how much memory was allocated (I’ve tried up to 16g) and I have had the full test run succeed with a max of only 512m. In addition, upon the OOME, the worker thread still hangs without directly reporting the error (it may be on the individual test log after a CI job has been killed because of timeout). Finally, these worker processes seem to cause issues (especially upon failure) with other jobs running builds due to cache locks (so, the other builds timeout after one minute).

hung-tests.zip (3.9 KB)

mark_vieira · February 2, 2017, 12:06am

These types of issues are typically due to tests leaking resources in some way. You can try setting the fork options so that a new test JVM is created every so often.

test {
    forkEvery 100 // number of test classes to run before creating a new forked process
}

mondrejko · February 2, 2017, 3:37am

I will give the forkEvery a try. This may not be practical to do long term as each fork will create a database test schema for execution. But, if it works I could push back to the infrastructure team to identify and address any resource leak.

mondrejko · February 2, 2017, 2:16pm

It appears that the issue can happen when running the test methods within a single class, so forkEvery doesn’t help.

When running with --debug, I see the following messages when the test appears hung (note, not sure yet if these are typical debug message or indicative of an issue):

14:09:52.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:09:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:09:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:09:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:09:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:09:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:09:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:02.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:10:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:12.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:10:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:22.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:10:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:32.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:10:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:42.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:10:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:52.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:10:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:10:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:10:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:10:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:02.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:11:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:12.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:11:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:22.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:11:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:32.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:11:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:42.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:11:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:52.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:11:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:11:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:11:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:11:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:02.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:12:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:12.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:12:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:12.374 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:12.374 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:12.374 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:12.374 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:22.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:12:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:32.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:12:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:42.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:12:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:52.373 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:12:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:52.374 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:12:52.374 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:12:52.375 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:12:52.375 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:02.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:13:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:12.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:13:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:22.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:13:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:32.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:13:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:32.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:32.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:42.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:13:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:42.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:42.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:52.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:13:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:52.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:13:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:13:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:13:52.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:14:02.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:14:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:14:02.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:14:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:14:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:14:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:14:02.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:14:12.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:14:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:14:12.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:14:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:14:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:14:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:14:12.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:14:22.372 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
14:14:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:14:22.372 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:14:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
14:14:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
14:14:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired.
14:14:22.373 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.

mondrejko · February 2, 2017, 2:50pm

Also, the following stacktrace (from jstack) seems to indicate that the worker is blocked waiting to be able to write (back to the main process?) test output/logging/something… Is this blocking expected?

sun.nio.ch.EPollArrayWrapper.epollWait(long, int, long, int) @bci=0 (Interpreted frame)
sun.nio.ch.EPollArrayWrapper.poll(long) @bci=18, line=269 (Interpreted frame)
sun.nio.ch.EPollSelectorImpl.doSelect(long) @bci=28, line=79 (Interpreted frame)
sun.nio.ch.SelectorImpl.lockAndDoSelect(long) @bci=37, line=87 (Interpreted frame)
sun.nio.ch.SelectorImpl.select(long) @bci=30, line=98 (Interpreted frame)
sun.nio.ch.SelectorImpl.select() @bci=2, line=102 (Interpreted frame)
org.gradle.internal.remote.internal.inet.SocketConnection$SocketOutputStream.waitForWriteBufferToDrain() @bci=58, line=276 (Interpreted frame)
org.gradle.internal.remote.internal.inet.SocketConnection$SocketOutputStream.writeBufferToChannel() @bci=40, line=250 (Compiled frame)
org.gradle.internal.remote.internal.inet.SocketConnection$SocketOutputStream.write(byte[], int, int) @bci=110, line=233 (Compiled frame)
com.esotericsoftware.kryo.io.Output.flush() @bci=38, line=154 (Compiled frame)
com.esotericsoftware.kryo.io.Output.require(int) @bci=82, line=134 (Compiled frame)
com.esotericsoftware.kryo.io.Output.writeString_slow(java.lang.CharSequence, int, int) @bci=49, line=419 (Compiled frame)
com.esotericsoftware.kryo.io.Output.writeString(java.lang.CharSequence) @bci=199, line=355 (Compiled frame)
org.gradle.internal.serialize.kryo.KryoBackedEncoder.writeString(java.lang.CharSequence) @bci=33, line=70 (Compiled frame)
org.gradle.api.internal.tasks.testing.worker.TestEventSerializer$DefaultTestOutputEventSerializer.write(org.gradle.internal.serialize.Encoder, org.gradle.api.internal.tasks.testing.DefaultTestOutputEvent) @bci=27, line=139 (Compiled frame)
org.gradle.api.internal.tasks.testing.worker.TestEventSerializer$DefaultTestOutputEventSerializer.write(org.gradle.internal.serialize.Encoder, java.lang.Object) @bci=10, line=126 (Compiled frame)

mondrejko · February 2, 2017, 3:24pm

A further stacktrace from within the thread running TestNG appears hung waiting for a debug log message to be written (should also be seen in the jstack output attached). This appears to point to Gradle having an issue handling log messages through the test event serializer/logger.

Thread 27065: (state = BLOCKED)

java.nio.HeapByteBuffer.(int, int) @bci=6, line=57 (Compiled frame)
java.nio.ByteBuffer.allocate(int) @bci=18, line=331 (Compiled frame)
org.gradle.internal.io.StreamByteBuffer.readAsCharBuffer(java.nio.charset.Charset) @bci=467, line=213 (Compiled frame)
org.gradle.internal.io.StreamByteBuffer.doReadAsString(java.nio.charset.Charset) @bci=20, line=168 (Compiled frame)
org.gradle.internal.io.StreamByteBuffer.readAsString(java.nio.charset.Charset) @bci=6, line=159 (Compiled frame)
org.gradle.internal.io.StreamByteBuffer.readAsString() @bci=8, line=154 (Compiled frame)
org.gradle.internal.io.LineBufferingOutputStream.flush() @bci=8, line=93 (Compiled frame)
org.gradle.internal.io.LineBufferingOutputStream.write(int) @bci=95, line=80 (Compiled frame)
java.io.OutputStream.write(byte[], int, int) @bci=69, line=116 (Compiled frame)
java.io.PrintStream.write(byte[], int, int) @bci=16, line=480 (Compiled frame)
org.gradle.internal.io.LinePerThreadBufferingOutputStream.write(byte[], int, int) @bci=12, line=206 (Compiled frame)
sun.nio.cs.StreamEncoder.writeBytes() @bci=120, line=221 (Compiled frame)
sun.nio.cs.StreamEncoder.implFlushBuffer() @bci=11, line=291 (Compiled frame)
sun.nio.cs.StreamEncoder.implFlush() @bci=1, line=295 (Compiled frame)
sun.nio.cs.StreamEncoder.flush() @bci=12, line=141 (Compiled frame)
java.io.OutputStreamWriter.flush() @bci=4, line=229 (Compiled frame)
org.apache.log4j.helpers.QuietWriter.flush() @bci=8, line=57 (Compiled frame)
org.apache.log4j.WriterAppender.subAppend(org.apache.log4j.spi.LoggingEvent) @bci=149, line=315 (Compiled frame)
org.apache.log4j.WriterAppender.append(org.apache.log4j.spi.LoggingEvent) @bci=19, line=159 (Compiled frame)
org.apache.log4j.AppenderSkeleton.doAppend(org.apache.log4j.spi.LoggingEvent) @bci=155, line=230 (Compiled frame)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(org.apache.log4j.spi.LoggingEvent) @bci=67, line=65 (Compiled frame)
org.apache.log4j.Category.callAppenders(org.apache.log4j.spi.LoggingEvent) @bci=57, line=203 (Interpreted frame)
org.apache.log4j.Category.forcedLog(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=19, line=388 (Compiled frame)
org.apache.log4j.Category.log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=63, line=853 (Compiled frame)
org.slf4j.impl.Log4jLoggerAdapter.debug(java.lang.String) @bci=16, line=209 (Compiled frame)

mark_vieira · February 2, 2017, 9:31pm

Have you tried setting memory settings on the test task itself? I’m not sure bumping the memory for the daemon will help in this instance.

https://docs.gradle.org/current/dsl/org.gradle.api.tasks.testing.Test.html#org.gradle.api.tasks.testing.Test:maxHeapSize

mondrejko · February 2, 2017, 11:20pm

Yes, the memory setting was done on the test process as that is where the OOME occurs.

jendrik · February 3, 2017, 8:33am

That the debug log messages of Log4j are send to Gradle, even if the log level is below debug, is due to the current implementation of logging in Gradle. It basically aggregates log messages from different sources (which can be different logging systems used by different libraries/plugins) and then filters them according to log level afterwards.

This is something we can certainly improve.

Still, the root of the problem seems to be something else. The above mentioned behaviour could lead to slowing things down (in cases of expensive logging), but should not lead to making them hang.

Is there a chance that you can provide an example that reproduces the behaviour or a heap dump? You can also send that directly to me or @mark_vieira.

mondrejko · February 3, 2017, 7:55pm

The attached zip contains a couple of heap reports from JProfiler:

HungHeap.zip (39.2 KB)

jendrik · February 8, 2017, 10:33am

Thanks doe the hep reports. Confirms that thing seem to be piling up in EndPointQueue. Unfortunately I don’t have a clue how that could be caused.

Can you send an abstracted version of your build file that shows the task configurations and general structure (without reference to concrete projects/artifacts)? Maybe we can reproduce the problem with that.

mondrejko · February 8, 2017, 9:59pm

Below is extracted from our plugin that configures testing with TestNG. We are currently using the existing ‘test’ task for unit tests, and a new ‘integrationTest’ task of type Test for running integration tests. This integrationTest task includes running the DB tests that are presenting the issue (all of our unit-tests run as expected).

        // configuration for test and integrationTest (and any additional Test task added)
        tasks.withType(Test) { task ->
            workingDir = project.file("${project.buildDir}/${task.name}-output")
            workingDir.mkdirs()

            systemProperties( _system properties set for tests_ )
            maxHeapSize = testMemoryMaximumSize // default = 512m
            jvmArgs '-XX:MaxPermSize=64m', '-XX:-UseSplitVerifier'

            testLogging {
                // lifecycle
                displayGranularity 4
                events 'failed'
                exceptionFormat 'short'
                showCauses true
                showStandardStreams = false

                info {
                    displayGranularity 4
                    events 'passed', 'skipped', 'failed'
                    showStandardStreams = false
                }

                debug {
                    events 'started', 'passed', 'skipped', 'failed'
                    exceptionFormat 'full'
                    showStandardStreams = true
                }
            }

            reports.html.enabled = // true (false for CI builds)

            afterSuite { desc, result ->
                if (!desc.parent) {
                    logger.lifecycle "${task.name.capitalize()} task tests run: ${result.testCount}, Successful: ${result.successfulTestCount}, Failures: ${result.failedTestCount}, Skipped: ${result.skippedTestCount}"
                }
            }
        }

// test task configuration

        test {
            String suiteFile = _path to suite.xml_

            inputs.property('testngSuiteFile', suiteFile)
            inputs.files project.files(suiteFile) { builtBy 'generateTestNGConfig' }
            outputs.upToDateWhen { !project.generateTestNGConfig.didWork }

            useTestNG {
                suites suiteFile
                useDefaultListeners(false /* true for CI*/)
            }
        }

// integrationTest task configuration

integrationTest {
    project.check.dependsOn this
    shouldRunAfter 'test'

    inputs.files project.files(integrationSuiteFile) { builtBy 'generateTestNGIntegrationConfig' }
    outputs.upToDateWhen { !project.generateTestNGIntegrationConfig.didWork }

    useTestNG {
        suites integrationSuiteFile
        useDefaultListeners(false /* true for CI */)
    }
    reports.html.destination = "${project.buildDir}/reports/integrationTests"
}

jendrik · February 9, 2017, 3:44pm

Thanks for the additional information Michael.

I did some experiments with simulating tests with a lot of logging.

Here is my assumption:
Some listener is collecting data from tests in-memory. The Gradle daemon runs out of memory. You get a OOME or it just becomes unresponsive (the build hangs). With simulating this, I was able to reproduce similar heap reports as you.

If my assumption is correct. There are two issues here I think:

(1) Gradle should handle this situations better. At least we should improve error reporting here. I will open an issue on GitHub for this.

(2) You probably should not produce that much output in the first place (?)

You wrote:

The test implement uses a thirdparty library, dbunit, that may contains lots and lots of logging (when run previously, we had this debugging mostly depressed). However, I have been able to trace the root of the issues we see to these (even suppressed) log messages seemingly being sent to the Gradle main build process.

How do you suppress the log messages? Something is not working here. You should be able to suppress them at least in a way that they are not send out from the worker. That should work with the current logging implementation.

Can you confirm that the problem is related to listeners? When you run the tests locally from the shell, without any additional listeners, do you still see the problem?

jendrik · February 9, 2017, 5:08pm

mondrejko · February 9, 2017, 6:23pm

I agree. Unfortunately, the log messages are coming from a thirdparty library. I will look into methods of suppressing these log messages, but the issue appears even when debug logging is not active. That is, in the Gradle event listener, I still see these debug log messages transmitted, even when suppressed. (I believe that this is what you are saying about Gradle handling the logging better.)

As mentioned, the debug logging is typically disabled, but still seen going to the Gradle test event listener. How can I stop the messages from getting sent out from the listener?

No, the issue has only been seen when running tests within a Grade build. It occurs both with and without the Gradle daemon.

jendrik · February 10, 2017, 11:44am

As mentioned, the debug logging is typically disabled

Where/how is this configured? Logging configuration is always confusing. The configuration you posted above with testLogging only concerns the logging Gradle is performing.

dbunit uses SLF4J. So you might have some logger configuration (simple-logger, log4j, …) on your classpath that is applied. Could you check what else might be there?

I set up a test project with dbunit without anything else and then by default the NoOp logger is used and no log events are send to Gradle:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Only when I add a logger implementation to my dependencies and configure it (e.g. by adding a
test/resources/simplelogger.properties file or by adding test { jvmArgs '-Dorg.slf4j.simpleLogger.defaultLogLevel=debug' } to the build script I get all these extensive log messages.

mondrejko · February 10, 2017, 12:46pm

I noticed this after your last message as well, that it did not appear that the underlying logging mechanism was configured (and no message indicating such). I then added the system property ‘log4j.configuration=file:’ to the TestNG system properties. Unfortunately, this does not seem to have solved the issue. I ran both the daemon and test worker thread with 16g max heap size and the daemon still produces OOME (last run I had 14 such OOME alerts before I killed the build, after many hours).

I do believe this is the correct path as I have no problem recommending to developers that they should only run --debug (at least on these tests) when running a single test method/class/whatever is appropriate. If I can suppress the logging that causes the OOMEs…

jendrik · February 10, 2017, 1:51pm

the daemon still produces OOME

Are you saying you successfully disabled logging and are still seeing the OOME? Or are you not sure if you disabled it?

If it did not work (or if you don’t know), can you double check which logger implementation is really used? Might be that it is not log4j, because there is some other (possibly conflicting) slf4j configuration on the classpath.

You could do something like this in a test to check/confirm which implementation is really in the end:

System.out.println("Logger Implementation: " + LoggerFactory.getLogger(TestClass.class).getClass());

jendrik · February 10, 2017, 2:16pm

mondrejko · February 10, 2017, 3:37pm

I was saying that I thought I had the logger configuration correct (one of my test suites passed that had failed before). However, I have since realized that the logging was not configured correctly- the correct logger implementation was picked up, but misconfigured and was still logging everything to the console. I found that the log4j configuration used for log4j had not been updated for log4j2 when that upgrade was done.

I have corrected this configuration and now have the dbunit log message suppressed. I am now attempting the test runs for various components that had been failing previously.

Topic		Replies	Views
Gradle hangs if worker process fails with e.g. OutOfMemory exception Old Forum Archive	3	606	January 24, 2013
TestNG parallel test execution hangs up Help/Discuss	5	2119	October 21, 2016
Testng test hangs and never exits Old Forum Archive	4	3476	January 12, 2015
Gradle test hangs forever Help/Discuss	9	13041	December 10, 2019
Gradle hangs indefinately after finishing tests run in parallel Old Forum Archive	6	4133	April 22, 2013

Hung worker/OOME running TestNG

Related topics