背景

最近公司對(duì)框架做了一波改造奖恰，改造后的應(yīng)用上線后，在QPS到達(dá)一定程度的時(shí)候發(fā)現(xiàn)會(huì)有很多請(qǐng)求超時(shí)，從鏈路上看是我自己的服務(wù)造成的超時(shí)秩伞。但是從監(jiān)控看我服務(wù)的請(qǐng)求量和響應(yīng)時(shí)間都很正常吁伺，而從調(diào)用方的監(jiān)控來(lái)看饮睬，服務(wù)一部分請(qǐng)求處于超時(shí)狀態(tài)，于是我開始了兩天的debug

Debug

首先請(qǐng)求超時(shí)篮奄，第一個(gè)反應(yīng)就是是否有線程在阻塞捆愁。于是jstack看了一下發(fā)現(xiàn)并沒有奇怪的等待(由于當(dāng)時(shí)是在機(jī)器上看沒有備份下來(lái)，這里就沒有貼出來(lái)了)

然后決定dump一下數(shù)據(jù)窟却，看看里邊有沒有比較可疑的地方昼丑。如下圖我們看到所有線程都在等一個(gè)空隊(duì)列，這應(yīng)該屬于正晨浜眨現(xiàn)象菩帝，隊(duì)列里都沒有請(qǐng)求大家肯定在等了。但是這里有個(gè)疑點(diǎn)茬腿，請(qǐng)求量這么大為什么大家都在等一個(gè)空隊(duì)列呢呼奢？請(qǐng)求應(yīng)該已經(jīng)進(jìn)來(lái)了，不應(yīng)該出現(xiàn)隊(duì)列里沒請(qǐng)求的情況切平。

dump數(shù)據(jù)

與此同時(shí)握础，我上線了一段新代碼，在所有可能的耗時(shí)操作的前后都進(jìn)行了計(jì)時(shí)打點(diǎn)揭绑，試圖找到一個(gè)請(qǐng)求中最耗時(shí)的部分到底是哪弓候。結(jié)果讓人大跌眼鏡，所有的請(qǐng)求耗時(shí)都特別短(ms級(jí)別)他匪，理論上不可能造成客戶端請(qǐng)求3秒超時(shí)的菇存。

懷疑人生

到此我有些驚慌失措，畢竟上線ddl就像考試時(shí)站在你旁邊一直盯著我的監(jiān)考老師一樣給我無(wú)限的壓力邦蜜。于是我開始看各種監(jiān)控依鸥，QPS正常，響應(yīng)時(shí)間正常悼沈，JVM正常贱迟，成功率下跌姐扮，【沒有可用線程異常】增加衣吠，【客戶端超時(shí)關(guān)閉連接異巢杳簦】增加，CPU正常缚俏，網(wǎng)絡(luò)IO正常惊搏，線程數(shù)正常，TCP連接數(shù)正常忧换，磁盤讀寫增加恬惯。

終于到了下一個(gè)發(fā)布窗口，我決定召喚出Java排障的必殺利器Arthas亚茬。本著做點(diǎn)什么比啥都不做好酪耳，就像做物理大題的時(shí)候先寫 “根據(jù)經(jīng)典力學(xué)公式可得” 一樣。于是在線上機(jī)器悄悄裝了個(gè)Arthas刹缝，直接監(jiān)控請(qǐng)求時(shí)長(zhǎng)超過(guò)1s的10個(gè)請(qǐng)求(正常我的請(qǐng)求都在幾毫秒之內(nèi))碗暗，結(jié)果還真的破案了！直接上Arthas破案圖(怕被查水表赞草，只截了最重要的部分)

Arthas命令:

trace xxx.xxx.ClassName methodName '#cost > 10' -n 10

最耗時(shí)的部分

trace的10個(gè)超時(shí)請(qǐng)求都是在Log:info()特別耗時(shí)讹堤！找到兇手對(duì)一個(gè)偵探來(lái)說(shuō)只是第一步而已，它的作案手法才是作為偵探的目標(biāo)厨疙。

確實(shí)，這個(gè)答案讓我既高興又費(fèi)解疑务，我的日志明明是異步打的啊沾凄，logback.xml中AsyncAppender寫的賊6的不可能出現(xiàn)寫日志阻塞請(qǐng)求的情況，而且我悄悄在線上悄悄debug實(shí)錘了logback讀取的配置文件就是異步的配置文件知允，甚至還用接口證明了這個(gè)日志就是異步寫的撒蟀，這不科學(xué)！

回想發(fā)布窗口之前我看到的異澄赂耄現(xiàn)象保屯，和日志有關(guān)的磁盤讀寫增加。磁盤讀寫增加涤垫，增加的量是多少呢姑尺？看了一下監(jiān)控著實(shí)令我震驚。圖合在一起看不到什么蝠猬，因?yàn)檎５那€直接看不到了切蟋，所以分開貼一下圖

正常的磁盤寫

超時(shí)機(jī)器的磁盤寫

到這里應(yīng)該可以猜測(cè)一下問(wèn)題的Root Cause了，日志量太多導(dǎo)致導(dǎo)致日志刷盤時(shí)大量占用CPU時(shí)間片榆芦，使得請(qǐng)求沒有足夠的時(shí)間片寫入網(wǎng)絡(luò)返回柄粹，這才使得我的每個(gè)計(jì)時(shí)打點(diǎn)的時(shí)間都很短喘鸟，理論上請(qǐng)求很快就能處理完畢，但是由于沒有時(shí)間片把數(shù)據(jù)刷到網(wǎng)卡使得客戶端那邊遲遲收不到返回驻右。另外即便日志配置是異步的(通過(guò)上圖也能看到日志每個(gè)一個(gè)固定的是時(shí)間段進(jìn)行磁盤寫)什黑，它通過(guò)一個(gè)buffer存儲(chǔ)日志再定期刷盤，但是實(shí)際刷盤依然是占用CPU時(shí)間片的堪夭。

發(fā)覺異常

那么問(wèn)題來(lái)了愕把，為什么之前的代碼就沒這個(gè)問(wèn)題呢？請(qǐng)求量都一樣茵瘾，日志量應(yīng)該也一樣啊礼华。后來(lái)發(fā)現(xiàn)，公司對(duì)框架做的改造會(huì)在其他地方多打幾個(gè)日志文件拗秘，除此之外當(dāng)程序發(fā)生業(yè)務(wù)異常時(shí)只會(huì)對(duì)最外層異常做處理圣絮，改造之后會(huì)對(duì)內(nèi)部的每一個(gè)異常做處理。也就是說(shuō)不僅一條日志寫了多份文件雕旨，日志量也變多了不少扮匠。

那沒事了

OK，這個(gè)案子總算是破了凡涩，在我做了一波沒用日志精簡(jiǎn)以后棒搜，服務(wù)終于回到了往日的平靜，一切都這么和諧活箕，唯有頭發(fā)又少了幾根...

后記

Arthas真np(破音)! 建議大家都會(huì)使用這個(gè)工具?https://arthas.aliyun.com/doc/