一次由日志引發(fā)的嚴(yán)重性能問題的排查過程

一 現(xiàn)象描述

新系統(tǒng)上線后運行正常，但突然有一天客戶反饋登錄出現(xiàn)很慢的情況。那就先重現(xiàn)客戶的問題，在測試環(huán)境，單筆測試系統(tǒng)登錄發(fā)現(xiàn)響應(yīng)時間在100ms以內(nèi)，數(shù)據(jù)上看還是不錯的。但并發(fā)測試，結(jié)果竟然大跌眼鏡，在并發(fā)100用戶下，響應(yīng)時間飆升到20s左右，這結(jié)果完全超越了預(yù)期，也重現(xiàn)了客戶的問題，接下來就是排查問題、解決問題。。。。

二 問題排查

1.       問題是在多用戶并發(fā)下出現(xiàn)的，當(dāng)并發(fā)100用戶時，從Jmeter console看，吞吐量僅僅為4/s。

此時機器cpu使用率僅2%左右，磁盤、網(wǎng)絡(luò)都沒發(fā)現(xiàn)異常，是什么原因?qū)е抡埱箜憫?yīng)時間達到20s左右呢？初步猜測是數(shù)據(jù)庫層在并發(fā)下出現(xiàn)了鎖，于是按這個思路，排查數(shù)據(jù)庫層的情況。

2．再次并發(fā)測試，同時關(guān)注數(shù)據(jù)庫是否發(fā)生鎖表，從測試過程發(fā)現(xiàn)，未見鎖表，從抓到awr報告中也未發(fā)現(xiàn)驗證耗時的sql語句，排除了問題發(fā)生在數(shù)據(jù)庫層的想法。

     既然數(shù)據(jù)庫層沒有問題，就要考慮中間件層了，系統(tǒng)采用java開發(fā)，tomcat作為應(yīng)用服務(wù)器。于是，自然想到分析下系統(tǒng)進程的情況。

3． 再次并發(fā)測試，通過觀察java進程各線程的運行情況，發(fā)現(xiàn)并發(fā)時，top顯示沒有線程是running的，隱隱之中，已經(jīng)覺得離真相更近了一步。

  并發(fā)時，居然沒有線程在running，那它們在干什么呢？所以，需要排查下各個線程的狀態(tài)。

4.  使用jstack將進程的各線程的運行狀態(tài)輸出到日志，以便后續(xù)分析。

    命令格式：jstack pid > stack.log

    查看日志，有重大發(fā)現(xiàn)，大量線程是blocked的狀態(tài)，blcok的原因是在等待log相關(guān)的資源。

 至此，已經(jīng)基本判定引起問題的原因了，既然與日志有關(guān)，那就先將日志等級從debug調(diào)整為error，測試看下是否有變化。

5.  將日志等級從debug調(diào)整到error，再次并發(fā)測試，發(fā)現(xiàn)問題不在出現(xiàn)，tps上升到322/s左右，響應(yīng)時間90%line在740毫秒，cpu使用到40%-50%，一切開始正常了。

6. 現(xiàn)在已經(jīng)知道是由于日志配置導(dǎo)致的該問題，那么對日志配置再做一些測試看看情況。

首先日志輸出使用的log4j，日志優(yōu)先級從高到低分別是 ERROR、WARN、INFO、DEBUG。先前配置debug出現(xiàn)性能問題，現(xiàn)在配置error問題解決，再次嘗試配 置info，測試也未發(fā)現(xiàn)問題，也就是說，該問題只有在debug配置下才會出現(xiàn)。經(jīng)開發(fā)走讀代碼，發(fā)現(xiàn)在debug下才會記錄線程打印出的日志。這也再次印證了，debug日志配置引起的問題。

實際系統(tǒng)發(fā)布是按info配置的，但是客戶環(huán)境因人為調(diào)整了debug引起的，再次改到info問題就解決了。雖然現(xiàn)場問題暫時解決了，但為什么debug配置下引起該問題，需要進一步分析。

三 進一步分析

  從線程日志可以看出調(diào)用了org.apache.log4j.Category.callAppenders方法，該方法中有synchronized同步鎖，同步鎖在并發(fā)條件下會導(dǎo)致線程競爭，引起線程BLOCKED問題。

 因針對該問題的解決方法，尚未驗證，提供以下類似問題的解決方法，供參考：

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

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

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