一次由日誌引起的嚴重性能問題的排查過程

一 現象描述

 

新系統上線後運行正常，但忽然有一天客戶反饋登陸出現很慢的狀況。那就先重現客戶的問題，在測試環境，單筆測試系統登陸發現響應時間在100ms之內，數據上看仍是不錯的。但併發測試，結果居然大跌眼鏡，在併發100用戶下，響應時間飆升到20s左右，這結果徹底超越了預期，也重現了客戶的問題，接下來就是排查問題、解決問題。。。。

 

二 問題排查

1.       問題是在多用戶併發下出現的，當併發100用戶時，從Jmeter console看，吞吐量僅僅爲4/s。

此時機器cpu使用率僅2%左右，磁盤、網絡都沒發現異常，是什麼緣由致使請求響應時間達到20s左右呢？初步猜想是數據庫層在併發下出現了鎖，因而按這個思路，排查數據庫層的狀況。

2．再次併發測試，同時關注數據庫是否發生鎖表，從測試過程發現，未見鎖表，從抓到awr報告中也未發現驗證耗時的sql語句，排除了問題發生在數據庫層的想法。

    

     既然數據庫層沒有問題，就要考慮中間件層了，系統採用java開發，tomcat做爲應用服務器。因而，天然想到分析下系統進程的狀況。

 

3． 再次併發測試，經過觀察java進程各線程的運行狀況，發現併發時，top顯示沒有線程是running的，隱隱之中，已經以爲離真相更近了一步。

     

  併發時，竟然沒有線程在running，那它們在幹什麼呢？因此，須要排查下各個線程的狀態。

 

4.  使用jstack將進程的各線程的運行狀態輸出到日誌，以便後續分析。

    命令格式：jstack pid > stack.log

    查看日誌，有重大發現，大量線程是blocked的狀態，blcok的緣由是在等待log相關的資源。

    

 至此，已經基本斷定引發問題的緣由了，既然與日誌有關，那就先將日誌等級從debug調整爲error，測試看下是否有變化。

 

5.  將日誌等級從debug調整到error，再次併發測試，發現問題不在出現，tps上升到322/s左右，響應時間90%line在740毫秒，cpu使用到40%-50%，一切開始正常了。

 

6. 如今已經知道是因爲日誌配置致使的該問題，那麼對日誌配置再作一些測試看看狀況。

首先日誌輸出使用的log4j，日誌優先級從高到低分別是 ERROR、WARN、INFO、DEBUG。先前配置debug出現性能問題，如今配置error問題解決，再次嘗試配 置info，測試也未發現問題，也就是說，該問題只有在debug配置下才會出現。經開發走讀代碼，發如今debug下才會記錄線程打印出的日誌。這也再次印證了，debug日誌配置引發的問題。

 

實際系統發佈是按info配置的，可是客戶環境因人爲調整了debug引發的，再次改到info問題就解決了。雖然現場問題暫時解決了，但爲何debug配置下引發該問題，須要進一步分析。

 

 

三 進一步分析

  從線程日誌能夠看出調用了org.apache.log4j.Category.callAppenders方法，該方法中有synchronized同步鎖，同步鎖在併發條件下會致使線程競爭，引發線程BLOCKED問題。

 

 因針對該問題的解決方法，還沒有驗證，提供如下相似問題的解決方法，供參考：

  1.使用Apache log 解決這個問題，代碼以下：

    private static final Log log = LogFactory.getLog("xxx");

2.  修改log4j配置文件，添加緩衝配置項；