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

一 現象描述

新系統上線后運行正常，但突然有一天客戶反饋登錄出現很慢的情況。那就先重現客戶的問題，在測試環境，單筆測試系統登錄發現響應時間在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配置文件，添加緩沖配置項；