記錄一次由于logback死鎖引起的生產(chǎn)事故

問題表象:

  • 某provider服務(wù)8個容器中的1個出現(xiàn)假死:日志突然中斷打印,連接數(shù)突然增加。
  • 本機房的springboot admin經(jīng)常報警:provider down。但是另一個機房一切正常。
  • 由于各種原因,故障容器被銷毀,無法查看應(yīng)用日志信息。
  • 后續(xù)幾天問題沒復(fù)現(xiàn)。

分析過程

  • 網(wǎng)絡(luò)排查:從springboot admin 長ping provider,一切正常。
  • 磁盤IO:同樣沒發(fā)現(xiàn)問題。

基本診斷是應(yīng)用問題:

  • 先看了服務(wù)之間調(diào)用的超時時間,發(fā)現(xiàn)開發(fā)人員竟然沒有設(shè)置,于是排查是不是調(diào)用后端服務(wù)超時,連接不釋放導(dǎo)致。查看正常容器日志,高峰期最大不超過20個線程。所以應(yīng)該不是這個原因。但是要求開發(fā)后續(xù)要修改:必須設(shè)置超時時間。
  • 查看代碼和依賴包里是否有類似exit的代碼導(dǎo)致tomcat假死,沒有發(fā)現(xiàn)。
  • JVM堆,tomcat配置參數(shù)OK,運行期占用較小,GC平穩(wěn)。
  • 非堆,運行平穩(wěn),代碼中也沒有new instance,ClassLoader等關(guān)鍵字。

診斷過程中,突然間另一個機房的容器出現(xiàn)了線程數(shù)暴漲的問題。

線程數(shù)暴漲.jpg

馬上登陸容器,取dump文件,打開后發(fā)現(xiàn)大量死鎖線程:

"http-nio-8080-exec-270" daemon prio=5 tid=59263 WAITING
    at sun.misc.Unsafe.park(Native Method)
    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)
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#49
    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)
       Local Variable: ch.qos.logback.classic.spi.LoggingEvent#170
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
    at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)
    at ch.qos.logback.classic.Logger.info(Logger.java:583)

再查看官網(wǎng)的:https://jira.qos.ch/browse/LOGBACK-1378
發(fā)現(xiàn) logback1.1.11有死鎖問題。作者回復(fù)已在 logback1.2.x已經(jīng)解決。升級版本繼續(xù)觀察吧。

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成,瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明:文章內(nèi)容(如有圖片或視頻亦包括在內(nèi))由作者上傳并發(fā)布,文章內(nèi)容僅代表作者本人觀點,簡書系信息發(fā)布平臺,僅提供信息存儲服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容