背景

最近公司對(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)，于是我開(kāi)始了兩天的debug

Debug

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

然后決定dump一下數(shù)據(jù)，看看里邊有沒(méi)有比較可疑的地方。如下圖我們看到所有線程都在等一個(gè)空隊(duì)列，這應(yīng)該屬于正常現(xiàn)象，隊(duì)列里都沒(méi)有請(qǐng)求大家肯定在等了。但是這里有個(gè)疑點(diǎn)，請(qǐng)求量這么大為什么大家都在等一個(gè)空隊(duì)列呢？請(qǐng)求應(yīng)該已經(jīng)進(jìn)來(lái)了，不應(yīng)該出現(xiàn)隊(duì)列里沒(méi)請(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ú)限的壓力。于是我開(kāi)始看各種監(jiān)控，QPS正常，響應(yīng)時(shí)間正常，JVM正常，成功率下跌，【沒(méi)有可用線程異?！吭黾?，【客戶端超時(shí)關(guān)閉連接異?！吭黾樱珻PU正常，網(wǎng)絡(luò)IO正常，線程數(shù)正常，TCP連接數(shù)正常，磁盤(pán)讀寫(xiě)增加。

終于到了下一個(gè)發(fā)布窗口，我決定召喚出Java排障的必殺利器Arthas。本著做點(diǎn)什么比啥都不做好，就像做物理大題的時(shí)候先寫(xiě) “根據(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寫(xiě)的賊6的不可能出現(xiàn)寫(xiě)日志阻塞請(qǐng)求的情況，而且我悄悄在線上悄悄debug實(shí)錘了logback讀取的配置文件就是異步的配置文件，甚至還用接口證明了這個(gè)日志就是異步寫(xiě)的，這不科學(xué)！

回想發(fā)布窗口之前我看到的異?，F(xiàn)象，和日志有關(guān)的磁盤(pán)讀寫(xiě)增加。磁盤(pán)讀寫(xiě)增加，增加的量是多少呢？看了一下監(jiān)控著實(shí)令我震驚。圖合在一起看不到什么，因?yàn)檎５那€直接看不到了，所以分開(kāi)貼一下圖

正常的磁盤(pán)寫(xiě)

超時(shí)機(jī)器的磁盤(pán)寫(xiě)

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

發(fā)覺(jué)異常

那么問(wèn)題來(lái)了，為什么之前的代碼就沒(mé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ō)不僅一條日志寫(xiě)了多份文件，日志量也變多了不少。

那沒(méi)事了

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

后記

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