Details
Blocker Description
We are using `logback-core-1.1.11` as our logging framework, and recently we found sometimes our web application is blocked and no response. After thread dump, we found that most of web threads (and many, around 150) are waiting for a lock in `OutputStreamAppender` as following stacktrace show:
"qtp956480812-17384" #17384 prio=5 os_prio=0 tid=0x00007f667400e800 nid=0x43f3 waiting on condition [0x00007f652d4d0000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000843211e8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414) at ch.qos.logback.classic.Logger.info(Logger.java:587) at cn.superid.auth.utils.PermissionUtil.hasPermission(PermissionUtil.java:31)
And following is the only thread which has the lock
"qtp956480812-17230" #17230 prio=5 os_prio=0 tid=0x00007f65c0017800 nid=0x4359 runnable [0x00007f65e5fe9000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) - locked <0x00000000830542d0> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:480) - locked <0x00000000830542b0> (a java.io.PrintStream) at java.io.FilterOutputStream.write(FilterOutputStream.java:97) at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37) at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:131) at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414) at ch.qos.logback.classic.Logger.info(Logger.java:587)
From the stacktrace, it seems no deadlock and application should not be blocked. But the actual phenomenon is no log, no response. So, what's the problem?
If you need more info, let me know. Thanks.