You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@dubbo.apache.org by "edwardlee03 (GitHub)" <gi...@apache.org> on 2018/10/10 05:37:00 UTC
[GitHub] [incubator-dubbo] edwardlee03 commented on issue #1932: Extremely many client threads are created though acvtives is set

We encountered the same exception log:
```
# 线程的runnable状态,表示线程cpu的时间片用完了，等待cpu时间片。
"http-nio-8080-exec-3" Id=158 RUNNABLE
        at java.lang.Throwable.getStackTrace(Throwable.java:816)
        at ch.qos.logback.classic.spi.CallerData.extract(CallerData.java:60)
        at ch.qos.logback.classic.spi.LoggingEvent.getCallerData(LoggingEvent.java:259)
        at ch.qos.logback.classic.pattern.LineOfCallerConverter.convert(LineOfCallerConverter.java:22)
        at ch.qos.logback.classic.pattern.LineOfCallerConverter.convert(LineOfCallerConverter.java:1)
        at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:36)
        at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:118)
        at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:141)
        at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:1)
        at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:130)
        at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)
        at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:279)
        # 持有写入同步锁
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
        at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
        ...

        Number of locked synchronizers = 2
        - java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        - java.util.concurrent.ThreadPoolExecutor$Worker@30865a90

"DubboClientHandler-10.1.19.153:20902-thread-38" Id=479943 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7 owned b
y "http-nio-8080-exec-3" Id=158
        at sun.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)

"http-nio-8080-exec-125" Id=479890 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7 owned by "http-nio-8080-exec-3"
 Id=158
        at sun.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)

"New I/O server worker #1-3" Id=479826 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7 owned by "http-nio-8080-exec-3" Id=158
        at sun.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)

"DubboZkclientConnector-SendThread(zkserver3.wacai.info:12181)" Id=479818 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@
688e0d7 owned by "http-nio-8080-exec-3" Id=158
        at sun.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)

"p-kafka-http-consumer-t0-for-loan.backend.marketing.apply.cancel-SendThread(serverzk3.qsh.wacai.info:2181)" Id=479810 WAITING on java.uti
l.concurrent.locks.ReentrantLock$NonfairSync@688e0d7 owned by "http-nio-8080-exec-3" Id=158
        at sun.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)

"DubboServerHandler-10.1.21.160:28080-thread-199" Id=420 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7 owned by "http-nio-8080-exec-3" Id=158
        at sun.misc.Unsafe.park(Native Method)
        -  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@688e0d7
        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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
```

记录一次由于logback死锁引起的生产事故
https://www.jianshu.com/p/3d04d2114abf

logback-xxx-1.1.x.jar deadlock found
https://jira.qos.ch/browse/LOGBACK-1378

![_56edb120-db8c-44db-95f6-c57d7bfa6f10](https://user-images.githubusercontent.com/1811851/46715020-cb1f8e80-cc90-11e8-8c6d-b60b564038d5.png)

**线上服务器CPU高，最终定位到 logback-xxx-1.1.x.jar 的死锁问题，原因是Logback Appender 是JVM单实例，这样可重入锁 lock 对象就是单点写并发同步。解决方法是升级到最新的 logback-xxx-1.2.x.jar。**


[ Full content available at: https://github.com/apache/incubator-dubbo/issues/1932 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org