解Bug之路-記一次線上請(qǐng)求偶爾變慢的排查
最近解決了個(gè)比較棘手的問(wèn)題,由于排查過(guò)程挺有意思,于是就以此為素材寫(xiě)出了本篇文章。
【資料圖】
Bug現(xiàn)場(chǎng)這是一個(gè)偶發(fā)的性能問(wèn)題。在每天幾百萬(wàn)比交易請(qǐng)求中,平均耗時(shí)大約為300ms,但總有那么100多筆會(huì)超過(guò)1s,讓我們業(yè)務(wù)耗時(shí)監(jiān)控的99.99線變得很尷尬。如下圖所示:為了精益求精,更為了消除這個(gè)尷尬的指標(biāo),筆者開(kāi)始探尋起這100多慢請(qǐng)求筆的原因。
先找一筆看看由于筆者寫(xiě)的框架預(yù)留了traceId,所以找到這筆請(qǐng)求的整個(gè)調(diào)用的鏈路還是非常簡(jiǎn)單的。而且通過(guò)框架中的攔截器在性能日志中算出了每一筆請(qǐng)求的耗時(shí)。這樣,非常便于分析鏈路到底是在哪邊耗時(shí)了。性能日志中的某個(gè)例子如下圖所示:
2020-09-0115:06:59.010[abcdefg,A->B,Dubbo-thread-1,ipA->ipB]B.facade,cost10ms
拉出來(lái)一整條調(diào)用鏈路后,發(fā)現(xiàn)最前面的B系統(tǒng)調(diào)用C系統(tǒng)就比較慢。后面鏈路還有幾個(gè)調(diào)用慢的,那先不管三七二十一,先分析B調(diào)用C系統(tǒng)吧。我們從監(jiān)控系統(tǒng)看出來(lái)正常的B系統(tǒng)調(diào)用C系統(tǒng)平均耗時(shí)只有20ms,這次的耗時(shí)增長(zhǎng)了10倍!正常思路,那當(dāng)然是C系統(tǒng)有問(wèn)題么,畢竟慢了10倍!去C系統(tǒng)的性能日志里面看看,
2020-09-0115:06:59.210[abcdefg,B->C,Dubbo-thread-1,ipB->ipC]C.facade,cost20ms
啪啪啪打臉,竟然只有20ms,和平均耗時(shí)差不多。難道問(wèn)題在網(wǎng)絡(luò)上?B到C之間由于丟包重傳所以到了200ms?
甩給網(wǎng)絡(luò)?由于筆者對(duì)TCP協(xié)議還是比較了解的,tcp第一次丟包重傳是200ms,那么加上C處理的時(shí)間20ms,即220ms必須得大于200ms。而由于Nagle和DelayAck造成的tcp延遲也僅僅是40ms,兩者相加60ms遠(yuǎn)遠(yuǎn)小于200ms,所以這個(gè)200ms是丟包或者DelayAck的概率不大。本著萬(wàn)一呢的態(tài)度,畢竟下絕對(duì)的判斷往往會(huì)被打臉,看了下我們的監(jiān)控系統(tǒng),發(fā)現(xiàn)當(dāng)時(shí)流量距離網(wǎng)卡容量只有1/10左右,距離打滿網(wǎng)卡還有非常遠(yuǎn)的距離。注意,這個(gè)監(jiān)控的是由KVM虛擬機(jī)虛擬出來(lái)的網(wǎng)卡。看了這個(gè)流量,筆者感覺(jué)網(wǎng)絡(luò)上問(wèn)題的概率不大。
GC了?筆者第二個(gè)想到的是GC了,但是觀察了B和C的當(dāng)時(shí)時(shí)刻的GC日志,非常正常,沒(méi)有FullGC,youngGC也在毫秒級(jí),完全不會(huì)有200ms這么長(zhǎng)。TCP重傳+雙方都youngGC?這個(gè)也太巧了點(diǎn)吧,也不是不可用。不過(guò)詳細(xì)的計(jì)算了時(shí)間點(diǎn),并納入了雙方機(jī)器的時(shí)鐘誤差后,發(fā)現(xiàn)基本不可能。
再看看其它幾筆盡然這個(gè)問(wèn)題每天有100多筆(當(dāng)然了,也不排除其中混雜了其它不同的問(wèn)題),那么就試試看看其它幾筆,有沒(méi)有什么共性。這一看,發(fā)現(xiàn)個(gè)奇怪的現(xiàn)象,就是有時(shí)候是A調(diào)用B慢,有時(shí)候是B調(diào)用C慢,還有時(shí)候是E調(diào)用F慢。他們唯一的共性就是耗時(shí)變長(zhǎng)了,但是這個(gè)耗時(shí)增加的比例有5倍的,有10倍的,完全沒(méi)有規(guī)律可循。這不禁讓筆者陷入了沉思。
尋找突破點(diǎn)既然通用規(guī)律只有變慢,暫時(shí)無(wú)法進(jìn)一步挖掘。那么還是去B系統(tǒng)上去看看情況吧,去對(duì)應(yīng)B系統(tǒng)上故意不用grep而是用less看了下,上下掃了兩眼。突然發(fā)現(xiàn),貌似緊鄰著的幾條請(qǐng)求都很慢,而且是無(wú)差別變慢!也就是說(shuō)B系統(tǒng)調(diào)用任何系統(tǒng)在這個(gè)時(shí)間點(diǎn)都有好幾倍甚至十幾倍的耗時(shí)!終于找到了一個(gè)突破點(diǎn),B系統(tǒng)本身或者其所屬的環(huán)境應(yīng)該有問(wèn)題!于是筆者用awk統(tǒng)計(jì)了下 B系統(tǒng)這個(gè)小時(shí)內(nèi)每分鐘的平均調(diào)用時(shí)長(zhǎng),用了下面這條命令:
cat性能日志|grep"時(shí)間點(diǎn)|awk-F"""{print$2,$5}"|.......|awk-F"""{sum[$1]+=$3;count[$1]+=1}END{for(iinsum){printi,sum[i]/count[i]}}"
發(fā)現(xiàn)
15:002015:012115:021515:0330.......15:06172.415:07252.415:08181.415:102015:102115:1022
在15:06-15:08這三分鐘之內(nèi),調(diào)用時(shí)間會(huì)暴漲!但奇怪的是B系統(tǒng)明明有幾十臺(tái)機(jī)器,只有這一臺(tái)在這個(gè)時(shí)間段內(nèi)會(huì)暴漲。難道這個(gè)時(shí)間有定時(shí)任務(wù)?筆者搜索了下B系統(tǒng)昨天的日志,發(fā)現(xiàn)在同樣的時(shí)間段內(nèi),還是暴漲了!再接著搜索其它調(diào)用慢的,例如E->F,發(fā)現(xiàn)他們也在15:06-15:08報(bào)錯(cuò)!于是筆者,一橫心,直接用awk算出了所有系統(tǒng)間調(diào)用慢機(jī)器白天內(nèi)的所有分鐘平均耗時(shí)(晚上的流量小不計(jì)入內(nèi)),發(fā)現(xiàn):所有調(diào)用慢的機(jī)器,都非常巧的在每個(gè)小時(shí)06-08分鐘之內(nèi)調(diào)用慢。再觀察下慢的請(qǐng)求,發(fā)現(xiàn)他們也全部是分布在不同小時(shí)的06-08分時(shí)間段內(nèi)!
定時(shí)任務(wù)?第一反應(yīng)是有定時(shí)任務(wù),查了下所有調(diào)用機(jī)器的crontab沒(méi)有問(wèn)題。問(wèn)了下對(duì)應(yīng)的開(kāi)發(fā)有沒(méi)有調(diào)度,沒(méi)有調(diào)度,而且那個(gè)時(shí)間段由于耗時(shí)的原因,每秒請(qǐng)求數(shù)反而變小了。翻了下機(jī)器監(jiān)控,也都挺正常。思維陷入了僵局,突然筆者靈光一閃,我們的應(yīng)用全部是在KVM虛擬機(jī)上,會(huì)不會(huì)是宿主機(jī)出了問(wèn)題。于是聯(lián)系了下SA,看看這些機(jī)器的宿主機(jī)是個(gè)什么情況。
每個(gè)變慢的機(jī)器的宿主機(jī)都有Redis!這一看就發(fā)現(xiàn)規(guī)律了,原來(lái)變慢的機(jī)器上都和Redis共宿主機(jī)!登陸上對(duì)應(yīng)的Redis服務(wù)器,發(fā)現(xiàn)CPU果然在那個(gè)時(shí)間點(diǎn)有尖峰。而這點(diǎn)尖峰對(duì)整個(gè)宿主機(jī)的CPU毫無(wú)影響(畢竟宿主機(jī)有64個(gè)核)。crontab -l 一下,果然有定時(shí)任務(wù),腳本名為Backup!它起始時(shí)間點(diǎn)就是從06分開(kāi)始往GlusterFS盤(pán)進(jìn)行備份,從06分開(kāi)始CPU使用率開(kāi)始上升=>07分達(dá)到頂峰=>08分降下來(lái),和耗時(shí)曲線完全一致!原來(lái)Redis往Gluster盤(pán)備份占據(jù)了大量的IO操作,所以導(dǎo)致宿主機(jī)上的其它應(yīng)用做IO操作時(shí)會(huì)變得很慢,進(jìn)而導(dǎo)致但凡是這個(gè)備份時(shí)間內(nèi)系統(tǒng)間調(diào)用的平均耗時(shí)都會(huì)暴漲接近10倍,最終導(dǎo)致了高耗時(shí)的請(qǐng)求。
為什么調(diào)用請(qǐng)求超時(shí)1s的概率這么低由于我們線上每個(gè)應(yīng)用都有幾十臺(tái)機(jī)器,而基本每次調(diào)用只有幾十毫秒。所以只有這個(gè)請(qǐng)求連續(xù)落到三個(gè)甚至多個(gè)和Redis共宿主機(jī)的系統(tǒng)里面才會(huì)導(dǎo)致請(qǐng)求超過(guò)1s,這樣才能被我們的統(tǒng)計(jì)腳本監(jiān)測(cè)到,而那些大量的正常請(qǐng)求完全拉平了平均值。
解決方案我們將線上實(shí)時(shí)鏈路的系統(tǒng)從對(duì)應(yīng)有Redis的宿主機(jī)中遷移出來(lái),再也沒(méi)有那個(gè)尷尬的1s了。
借此推薦一本書(shū)。
這本書(shū)豆瓣評(píng)價(jià)8.6分,在詳細(xì)講解性能問(wèn)題排查的同時(shí)補(bǔ)充了大量的基礎(chǔ)知識(shí),是本很不錯(cuò)的書(shū)。總結(jié)在遇到問(wèn)題,并且思路陷入僵局時(shí),可以通過(guò)一些腳本工具,例如grep以及awk或者其它一些工具對(duì)眾多日志進(jìn)行分析,不停的去尋找規(guī)律,從無(wú)序中找到有序,往往能夠產(chǎn)生意想不到的效果!歡迎大家加我公眾號(hào),里面有各種干貨,還有大禮包相送哦!
關(guān)鍵詞: 定時(shí)任務(wù) 有時(shí)候是 系統(tǒng)調(diào)用
相關(guān)閱讀
-
世界熱推薦:今晚7:00直播丨下一個(gè)突破...
今晚19:00,Cocos視頻號(hào)直播馬上點(diǎn)擊【預(yù)約】啦↓↓↓在運(yùn)營(yíng)了三年... -
NFT周刊|Magic Eden宣布支持Polygon網(wǎng)...
Block-986在NFT這樣的市場(chǎng),每周都會(huì)有相當(dāng)多項(xiàng)目起起伏伏。在過(guò)去... -
環(huán)球今亮點(diǎn)!頭條觀察 | DeFi的興衰與...
在比特幣得到機(jī)構(gòu)關(guān)注之后,許多財(cái)務(wù)專家預(yù)測(cè)世界將因?yàn)榧用茇泿诺?.. -
重新審視合作,體育Crypto的可靠關(guān)系才能雙贏
Block-987即使在體育Crypto領(lǐng)域,人們的目光仍然集中在FTX上。隨著... -
簡(jiǎn)訊:前端單元測(cè)試,更進(jìn)一步
前端測(cè)試@2022如果從2014年Jest的第一個(gè)版本發(fā)布開(kāi)始計(jì)算,前端開(kāi)發(fā)... -
焦點(diǎn)熱訊:劉強(qiáng)東這波操作秀
近日,劉強(qiáng)東發(fā)布京東全員信,信中提到:自2023年1月1日起,逐步為...