Deadlock on attempt to shutdown forked JVM/worker threads

[Dmitry Vyazelenko]

Hi,

I've got a deadlock from a benchmark that uses Spring framework (i.e. it creates Spring ApplicationContext
in @Setup(Level.Trial)/Scope.Benchmark). The benchmark itself is started with 4 threads. And finally
the benchmark method was failing with exception (internal issue) and "-foe true" was specified.

At the point when exception is thrown there is attempt to shutdown worker threads and also Spring
tries to shutdown itself. This results in the deadlock:
Found one Java-level deadlock:
=============================
"Thread-0":
  waiting to lock monitor 0x000000001131f088 (object 0x00000007059573f0, a org.openjdk.jmh.runner.link.BinaryLinkClient$ForwardingPrintStream),
  which is held by "Thread-5"
"Thread-5":
  waiting to lock monitor 0x0000000011321398 (object 0x00000007058d89a0, a java.lang.Object),
  which is held by "Thread-0"

Java stack information for the threads listed above:
===================================================
"Thread-0":
 at java.io.PrintStream.flush(PrintStream.java:337)
 - waiting to lock <0x00000007059573f0> (a org.openjdk.jmh.runner.link.BinaryLinkClient$ForwardingPrintStream)
 at org.openjdk.jmh.util.FileUtils.safelyClose(FileUtils.java:202)
 at org.openjdk.jmh.runner.link.BinaryLinkClient.close(BinaryLinkClient.java:77)
 - locked <0x00000007058d89a0> (a java.lang.Object)
 at org.openjdk.jmh.runner.ForkedMain$1.run(ForkedMain.java:103)
"Thread-5":
 at org.openjdk.jmh.runner.link.BinaryLinkClient.pushFrame(BinaryLinkClient.java:69)
 - waiting to lock <0x00000007058d89a0> (a java.lang.Object)
 at org.openjdk.jmh.runner.link.BinaryLinkClient.access$000(BinaryLinkClient.java:48)
 at org.openjdk.jmh.runner.link.BinaryLinkClient$ForwardingPrintStream$1.write(BinaryLinkClient.java:156)
 at java.io.PrintStream.write(PrintStream.java:480)
 - locked <0x00000007059573f0> (a org.openjdk.jmh.runner.link.BinaryLinkClient$ForwardingPrintStream)
 at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
 at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
 at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
 at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
 - locked <0x0000000705a5bc08> (a java.io.OutputStreamWriter)
 at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
 at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
 at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
 at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
 at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
 - locked <0x0000000705a5b3f0> (a org.apache.log4j.ConsoleAppender)
 at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
 at org.apache.log4j.Category.callAppenders(Category.java:206)
 - locked <0x0000000705a4c760> (a org.apache.log4j.spi.RootLogger)
 at com.xxx.xxx.logging.DispatcherLogHandler.append(DispatcherLogHandler.java:81)
 at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
 - locked <0x0000000705a5bd80> (a com.xxx.xxx.logging.DispatcherLogHandler)
 at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
 at org.apache.log4j.Category.callAppenders(Category.java:206)
 - locked <0x0000000705a4c6b0> (a org.apache.log4j.Logger)
 at org.apache.log4j.Category.forcedLog(Category.java:391)
 at org.apache.log4j.Category.log(Category.java:856)
 at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:601)
 at org.apache.commons.logging.impl.SLF4JLocationAwareLog.info(SLF4JLocationAwareLog.java:159)
 at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:873)
 at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:809)

I'm also attaching full stacktrace (the internal package names were changed to protect the innocent).

Unfortunately I don't have a standalone reproducible benchmark that I can share.

Best regards,
Dmitry
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: ForkedMain-full-stack-trace.txt
URL: <http://mail.openjdk.java.net/pipermail/jmh-dev/attachments/20140814/53d69fda/ForkedMain-full-stack-trace-0001.txt>