一 現(xiàn)象描述

專業(yè)從事成都做網(wǎng)站、成都網(wǎng)站建設(shè),高端網(wǎng)站制作設(shè)計(jì),重慶小程序開發(fā),網(wǎng)站推廣的成都做網(wǎng)站的公司。優(yōu)秀技術(shù)團(tuán)隊(duì)竭力真誠(chéng)服務(wù)，采用H5建站+CSS3前端渲染技術(shù)，響應(yīng)式網(wǎng)站設(shè)計(jì)，讓網(wǎng)站在手機(jī)、平板、PC、微信下都能呈現(xiàn)。建站過(guò)程建立專項(xiàng)小組，與您實(shí)時(shí)在線互動(dòng)，隨時(shí)提供解決方案，暢聊想法和感受。

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

二 問(wèn)題排查

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

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

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

   

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

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

    

并發(fā)時(shí)，居然沒(méi)有線程在running，那它們?cè)诟墒裁茨?？所以，需要排查下各個(gè)線程的狀態(tài)。

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

   命令格式：jstack pid > stack.log

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

   

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

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

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

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

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

三 進(jìn)一步分析

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

因針對(duì)該問(wèn)題的解決方法，尚未驗(yàn)證，提供以下類似問(wèn)題的解決方法，供參考：

1.使用Apache log 解決這個(gè)問(wèn)題，代碼如下：

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

2.  修改log4j配置文件，添加緩沖配置項(xiàng)；

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

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

廣告

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