java - 为什么Throwable::printStackTrace持有PrintStream锁并导致回退死锁

Question

在不同线程中使用e.printStackTrace()和logback时发现死锁情况。线程转储如下。

在我看来，登录(试图在AsyncAppender-Worker-Thread-1中使用)试图获取PrintStream锁，该锁已由main thread的java.lang.Throwable$WrappedPrintStream.println拥有。如果是这样，为什么printStackTrace继续持有PrintStream的锁(因为打印完成后它应该释放它)？

线程转储用于main thread。

"main@1" prio=5 tid=0x1 nid=NA waiting
  java.lang.Thread.State: WAITING
     blocks AsyncAppender-Worker-Thread-1@831
      at sun.misc.Unsafe.park(Unsafe.java:-1)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
      at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
      at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:139)
      at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:130)
      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
      at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
      at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
      at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
      at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
      at ch.qos.logback.classic.Logger.error(Logger.java:543)
      at com.side.stdlib.logging.StdOutErrLog$2.print(StdOutErrLog.java:43)
      at java.io.PrintStream.println(PrintStream.java:823)
      - locked <0x1183> (a com.side.stdlib.logging.StdOutErrLog$2)
      at java.lang.Throwable$WrappedPrintStream.println(Throwable.java:749)
      at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:698)
      at java.lang.Throwable.printStackTrace(Throwable.java:668)
      at java.lang.Throwable.printStackTrace(Throwable.java:644)
      at java.lang.Throwable.printStackTrace(Throwable.java:635)
      at com.side.SidekApi.sideAPIExecution(SidekApi.java:175)

线程AsyncAppender-Worker-Thread-1的线程转储

"AsyncAppender-Worker-Thread-1@831" daemon prio=5 tid=0xe nid=NA waiting for monitor entry
  java.lang.Thread.State: BLOCKED
     waiting for main@1 to release lock on <0x1183> (a com.side.stdlib.logging.StdOutErrLog$2)
      at java.io.PrintStream.write(PrintStream.java:478)
      at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
      at ch.qos.logback.core.joran.spi.ConsoleTarget$2.write(ConsoleTarget.java:55)
      at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:135)
      at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)
      at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)
      at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
      at ch.qos.logback.core.AsyncAppenderBase$Worker.run(AsyncAppenderBase.java:226)

看来https://bugs.openjdk.java.net/browse/JDK-6719464的情况有点类似，但那里没有答案。

Answer 1

如果logback worker线程无法完成，那一定是因为其阻塞队列已满。工作程序正在等待存放其日志条目，并且由于线程正在等待，我们知道它已释放队列上的锁，但它仍将锁保持在打印流上。控制台写入线程被阻塞，试图获取打印流上的锁定，以便将其写入控制台，因此它们处于死锁状态。

避免代码更改的一种最小修复方法是将控制台附加程序换成不需要在打印流上获得锁定的附加程序。

无论如何，需要锁定打印流都可能降低异步记录的好处。长期修复将涉及通过调用记录器(如slf4j)来替换printlns。