为什么Throwable::printStackTrace持有PrintStream的lock导致logback死锁

Question

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

在我看来，logback（在线程 AsyncAppender-Worker-Thread-1 中使用）试图获取 PrintStream 的锁，它已经被 main thread 的 [=17] 拥有=].如果是这样，为什么 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.print(StdOutErrLog.java:43)
      at java.io.PrintStream.println(PrintStream.java:823)
      - locked <0x1183> (a com.side.stdlib.logging.StdOutErrLog)
      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)
      at java.io.PrintStream.write(PrintStream.java:478)
      at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
      at ch.qos.logback.core.joran.spi.ConsoleTarget.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工作线程不能完成，那一定是因为它的阻塞队列满了。工作人员正在等待存放其日志条目，并且由于线程正在等待我们知道它释放了队列上的锁，但它仍然持有打印流上的锁。控制台写入线程在尝试获取打印流上的锁时被阻塞，这是写入控制台所需的锁，因此它们处于死锁状态。

避免代码更改的最小修复可能是将控制台附加程序换成不需要获取打印流锁的附加程序。

在任何情况下，需要锁定打印流可能会降低异步记录的好处。长期修复将涉及用对记录器（如 slf4j）的调用替换 printlns。

为什么Throwable::printStackTrace持有PrintStream的lock导致logback死锁

Why Throwable::printStackTrace holding lock of PrintStream and cause deadlock of logback

java

logging

multithreading

deadlock

logback