Tony Zeng created LOGBACK-1406:
----------------------------------
Summary: Seems all threads blocked
Key: LOGBACK-1406
URL: https://jira.qos.ch/browse/LOGBACK-1406
Project: logback
Issue Type: Bug
Components: logback-core
Environment: Linux ubuntu-100 4.4.0-116-generic #140-Ubuntu SMP Mon
Feb 12 21:23:04 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
java version "1.8.0_161"
Java(TM) SE Runtime Environment (build 1.8.0_161-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.161-b12, mixed mode)
Reporter: Tony Zeng
Assignee: Logback dev list
Attachments: dump
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:
{code:java}
"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)
{code}
And following is the only thread which has the lock
{code:java}
"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)
{code}
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.
--
This message was sent by Atlassian JIRA
(v7.3.1#73012)
_______________________________________________
logback-dev mailing list
[email protected]
http://mailman.qos.ch/mailman/listinfo/logback-dev
