一次由日志引發(fā)的嚴(yán)重性能問題的排查過程-創(chuàng)新互聯(lián)

一 現(xiàn)象描述

專業(yè)從事成都做網(wǎng)站、成都網(wǎng)站建設(shè),高端網(wǎng)站制作設(shè)計,重慶小程序開發(fā),網(wǎng)站推廣的成都做網(wǎng)站的公司。優(yōu)秀技術(shù)團隊竭力真誠服務(wù)，采用H5建站+CSS3前端渲染技術(shù)，響應(yīng)式網(wǎng)站設(shè)計，讓網(wǎng)站在手機、平板、PC、微信下都能呈現(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)時間達(dá)到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配置文件，添加緩沖配置項；

文章名稱：一次由日志引發(fā)的嚴(yán)重性能問題的排查過程-創(chuàng)新互聯(lián)
鏈接分享：http://muchs.cn/article16/djjidg.html

成都網(wǎng)站建設(shè)公司_創(chuàng)新互聯(lián)，為您提供App設(shè)計、商城網(wǎng)站、營銷型網(wǎng)站建設(shè)、微信小程序、動態(tài)網(wǎng)站、域名注冊

廣告

聲明：本網(wǎng)站發(fā)布的內(nèi)容（圖片、視頻和文字）以用戶投稿、用戶轉(zhuǎn)載內(nèi)容為主，如果涉及侵權(quán)請盡快告知，我們將會在第一時間刪除。文章觀點不代表本網(wǎng)站立場，如需處理請聯(lián)系客服。電話：028-86922220；郵箱：631063699@qq.com。內(nèi)容未經(jīng)允許不得轉(zhuǎn)載，或轉(zhuǎn)載時需注明來源： 創(chuàng)新互聯(lián)