前段時(shí)間同學(xué)反映我們活動(dòng)項(xiàng)目某個(gè)服務(wù)可用性出現(xiàn)抖動(dòng)，偶爾低于0.999。雖然看起來(lái)3個(gè)9的可用性相當(dāng)高，但是對(duì)于一個(gè) 10w+ qps 的服務(wù)來(lái)講，影響面就會(huì)被放大到不可接受的狀態(tài)。最大的影響就是調(diào)用預(yù)約接口在流量高峰期有不少超時(shí)。預(yù)約接口是一個(gè)qps相對(duì)高的接口，超時(shí)就顯得更加嚴(yán)重，而且這個(gè)問(wèn)題有一段時(shí)間，所以需要盡快排查清楚原因，進(jìn)行解決。服務(wù)可用性監(jiān)控如下：
【資料圖】
這個(gè)服務(wù)承載了很多活動(dòng)邏輯，用了很多技術(shù)棧如redis,mc,mysql,taishan,es,mongodb,databus等，是一個(gè)特大單體。所以業(yè)務(wù)與組件的復(fù)雜給排查問(wèn)題帶來(lái)不少挑戰(zhàn)。
猜想與否定了解基本情況后，知道可用性降低是由于超時(shí)導(dǎo)致，非其他錯(cuò)誤。進(jìn)行簡(jiǎn)要分析，能夠想出一些可能的原因，例如某些業(yè)務(wù)寫法導(dǎo)致性能問(wèn)題，異常流量，系統(tǒng)調(diào)用，網(wǎng)絡(luò)問(wèn)題，cpu throttle，中間件問(wèn)題（如redis,mysql），go調(diào)度，gc問(wèn)題等。至于是這8名嫌疑犯還是另有其人，需要結(jié)合實(shí)際現(xiàn)象進(jìn)行排除與論證，所以需要針對(duì)性的收集一些線索。
從上圖可以看出，這段時(shí)間流量比較規(guī)律性，并沒(méi)有出現(xiàn)異常波動(dòng)，似乎這個(gè)問(wèn)題與流量沒(méi)什么直接關(guān)系（背景中提到上游反饋高峰時(shí)段超時(shí),可能只是高峰期放大現(xiàn)象），所以排除是異常流量導(dǎo)致的。
可以看出很多接口的999分位都有同樣的問(wèn)題。如果只是某個(gè)業(yè)務(wù)寫法有問(wèn)題，僅僅影響該業(yè)務(wù)的接口。或者可能是業(yè)務(wù)寫法有問(wèn)題，影響了runtime，那就具體再看runtime的表現(xiàn)，所以當(dāng)時(shí)并沒(méi)有深入看業(yè)務(wù)代碼。
其實(shí)cpu throttle并不高，也問(wèn)過(guò)運(yùn)維，沒(méi)啥異常，不太像是導(dǎo)致超時(shí)的原因。中間有個(gè)小插曲：當(dāng)時(shí)有同學(xué)從cpu throttle導(dǎo)致超時(shí)這個(gè)猜想出發(fā)，發(fā)現(xiàn)預(yù)約業(yè)務(wù)內(nèi)存cache占用量比較大（占用大的話可能影響內(nèi)存的分配與釋放），嘗試減少預(yù)約業(yè)務(wù)內(nèi)存cache占用量。觀察一段時(shí)間，cpu throttle稍微有點(diǎn)降低，但可用性問(wèn)題依然沒(méi)有好轉(zhuǎn)。
后續(xù)通過(guò)查看trace，發(fā)現(xiàn)那段時(shí)間mysql與redis均有超時(shí)，細(xì)看給mysql的查詢時(shí)間只有0.01ms，mysql說(shuō)這鍋我不背的。
那redis層呢，給了21.45ms，似乎給比較充足的查詢時(shí)間，且redis有毛刺（不過(guò)毛刺時(shí)間點(diǎn)與可用性抖動(dòng)點(diǎn)對(duì)不上），但是redis內(nèi)心一萬(wàn)個(gè)不服啊。那行我們找對(duì)應(yīng)時(shí)間段，再多看幾個(gè)超時(shí)請(qǐng)求的trace，發(fā)現(xiàn)這些請(qǐng)求給redis的查詢時(shí)間都比較短，如下圖：
好吧，redis也可以鼓起勇氣說(shuō)，這鍋我也不背。
其他組件也同樣看過(guò)，都沒(méi)啥異常。那么問(wèn)題來(lái)了，組件們都不背，那到底誰(shuí)來(lái)背？那網(wǎng)絡(luò)，系統(tǒng)調(diào)用，go調(diào)度與gc，你們自己看著辦吧。
網(wǎng)絡(luò)說(shuō)你再仔細(xì)想想，不對(duì)啊，一個(gè)請(qǐng)求至少給了250ms的time_quota，你們最后只留給我和組件們那么點(diǎn)時(shí)間，redis 0.04ms，mysql 0.01ms。請(qǐng)問(wèn)扣除這點(diǎn)時(shí)間，剩余是誰(shuí)“消費(fèi)”了，應(yīng)該心知肚明了吧。說(shuō)到這，go調(diào)度，系統(tǒng)調(diào)用與gc主動(dòng)跳出來(lái)了。
排查思路現(xiàn)在的矛頭指向go runtime與系統(tǒng)調(diào)用。根據(jù)以往的經(jīng)驗(yàn)有以下幾種主要手段輔助定位：
采集pprof，用cpu profiler查看cpu占用，memory profiler查看gc問(wèn)題開啟GODEBUG=gctrace=1 ，可查看程序運(yùn)行過(guò)程中的GC信息。如果覺得是gc問(wèn)題，可查看服務(wù)可用性抖動(dòng)時(shí)間段gctrace是否異常，進(jìn)一步確認(rèn)問(wèn)題添加fgprof，輔助排查off-cpu可能性，off-cpu例如I/O、鎖、計(jì)時(shí)器、頁(yè)交換等，具體詳看鳥窩大佬文章：分析Go程序的Off-CPU性能（https://colobu.com/2020/11/12/analyze-On-CPU-in-go/）采集go trace，查看go調(diào)度問(wèn)題，例如gc、搶占調(diào)度等，真實(shí)反映當(dāng)時(shí)調(diào)度情況linux strace查看go運(yùn)行時(shí)調(diào)用了哪些系統(tǒng)調(diào)用導(dǎo)致超時(shí)分析gctrace分析根據(jù)以往一些經(jīng)驗(yàn)，gc有時(shí)候會(huì)影響系統(tǒng)的延時(shí)，所以先用gctrace看看這塊有沒(méi)有問(wèn)題。
從gctrace上可以看出，并發(fā)標(biāo)記和掃描的時(shí)間占用了860ms（圖中紅色框0.8+860+0.0668 ms中的860，一般gc問(wèn)題通?？催@塊區(qū)域），并發(fā)標(biāo)記和掃描比較占用cpu時(shí)間，這樣可能導(dǎo)致這段時(shí)間大多數(shù)cpu時(shí)間用于掃描，業(yè)務(wù)協(xié)程只能延遲被調(diào)度。后續(xù)與可用性未抖動(dòng)時(shí)間段的gctrace對(duì)比，發(fā)現(xiàn)并發(fā)標(biāo)記與掃描時(shí)間并沒(méi)有明顯增多，但從860ms的時(shí)長(zhǎng)上看，感覺也不是很合理，但沒(méi)有證據(jù)證明它就能夠?qū)е鲁瑫r(shí)抖動(dòng)，這塊異常先記著。
strace分析并未發(fā)現(xiàn)異常，都是一些正常的系統(tǒng)調(diào)用，看不出有明顯系統(tǒng)導(dǎo)致goroutine超時(shí)，所以"系統(tǒng)調(diào)用"這個(gè)嫌疑也暫時(shí)排除。
fgprof分析未見異常，結(jié)論同strace一樣，未出現(xiàn)off-cpu的協(xié)程堵塞。
go trace分析嘗試多次(超過(guò)20次)抓取go trace文件進(jìn)行分析。從trace文件上，可以明顯看到發(fā)生MARK ASSIST了，頓時(shí)心中有譜。多抓trace看看，還是有明顯的MARK ASSIST了現(xiàn)象，gc問(wèn)題應(yīng)該比較明顯了。
go heap 分析如果是gc問(wèn)題，那就和heap息息相關(guān)了。抓一段低峰期的heap，進(jìn)行分析。
inuse_space：
可見grpc連接占用了很大的一塊內(nèi)存，但這其實(shí)一般不太直接影響gc標(biāo)記和掃描，主要影響內(nèi)存的釋放。gc標(biāo)記和掃描還得看inuse_objects。
inuse_objects：
可以看到gcache中LFU生產(chǎn)的object數(shù)量高達(dá)100w+，而總共的object才300w。這塊明顯有問(wèn)題，那很可能就是它導(dǎo)致的問(wèn)題。
解決我們找到最大的嫌疑-gcache（該包引入項(xiàng)目已一年多）?？戳艘幌聵I(yè)務(wù)中使用gcache的情況及LFU的使用處
從用法上，未發(fā)現(xiàn)有什么問(wèn)題。便把問(wèn)題轉(zhuǎn)向gcache包本身。百度，google一頓搜索，源碼淺看了一下，也沒(méi)發(fā)現(xiàn)異常。github.com issue一搜，發(fā)現(xiàn)有人提過(guò)類似問(wèn)題https://github.com/bluele/gcache/issues/71。gcache LFU策略的Get方法存在內(nèi)存泄露（內(nèi)存大概泄露100M，占總內(nèi)存占用量2.5%，主要是產(chǎn)生大量指針對(duì)象）。具體bug是如何產(chǎn)生的，由于篇幅原因，這里不進(jìn)行贅述，可參考issue（https://github.com/bluele/gcache/issues/71）。后續(xù)將gcahce版本從v0.0.1升級(jí)至v0.0.2，該問(wèn)題得以解決。
gcache竟然是你啊，偷走了我0.001的服務(wù)可用性。
總結(jié)至此問(wèn)題排查與解決都告一段落了，但有些問(wèn)題還需總結(jié)與復(fù)盤。
從上面看，你可能想這問(wèn)題好像也很容易就排查到了，實(shí)際排查過(guò)程中并不順利。在進(jìn)行trace及heap分析時(shí)也是抓取了很多次，才抓到有效信息。后面發(fā)現(xiàn)某些gcache的過(guò)期時(shí)間只有5分鐘，過(guò)了這5分鐘，現(xiàn)場(chǎng)就沒(méi)了（如果能有自動(dòng)抓取能力，那該多方便），這讓懷疑是gc問(wèn)題的我們一段時(shí)間在自我肯定與否定中。中間產(chǎn)生更多猜想，例如懷疑定時(shí)器使用過(guò)多(業(yè)務(wù)代碼里面比較多后臺(tái)刷新配置的定時(shí)器)，導(dǎo)致業(yè)務(wù)邏輯調(diào)度延遲；grpc客戶端連接過(guò)多(2w+)，占用較大內(nèi)存，產(chǎn)生較多對(duì)象，影響gc；也有猜測(cè)是機(jī)器問(wèn)題；常駐內(nèi)存cache過(guò)多，內(nèi)部指針較多，影響gc掃描；甚至想用go ballast 絲滑的控制內(nèi)存等。
關(guān)于系統(tǒng)穩(wěn)定性這塊的小啟示：
第三方庫(kù)的引入還需慎重。本次問(wèn)題是第三方包bug導(dǎo)致的，所以引入包時(shí)需要考慮合理性，避免引入不穩(wěn)定因素。第三方包的安全漏洞問(wèn)題大家一般比較重視，bug卻常常被忽視?？芍贫ǖ谌桨囊霕?biāo)準(zhǔn)、編寫工具監(jiān)測(cè)第三方包issue的提出與解決，通知開發(fā)人員評(píng)估風(fēng)險(xiǎn)及更新包版本，從而做到第三方包的合理引入，快速發(fā)現(xiàn)issue以及修復(fù)。關(guān)于系統(tǒng)穩(wěn)定性這塊，基本上都是盡可能的添加監(jiān)控(包括系統(tǒng)，組件，go runtime維度)，通過(guò)報(bào)警及時(shí)發(fā)現(xiàn)問(wèn)題或隱患。至于go程序運(yùn)行時(shí)內(nèi)部的現(xiàn)場(chǎng)？似乎只能出問(wèn)題時(shí)在容器內(nèi)部或者借助公司自研平臺(tái)手動(dòng)抓取pprof，但多少存在一定的滯后性，有時(shí)候甚至現(xiàn)場(chǎng)都沒(méi)了。當(dāng)然也有人定時(shí)抓取pprof，但多少有點(diǎn)影響性能，姿勢(shì)也不夠優(yōu)雅。holmes(MOSN 社區(qū)性能分析利器)就顯得很有必要。通過(guò)相應(yīng)的策略，例如協(xié)程暴漲，cpu異常升高，內(nèi)存OOM等情況，自動(dòng)抓取，達(dá)到近似"無(wú)人值守"。既能夠較好的保留事故現(xiàn)場(chǎng)，也能提前暴漏一些隱患。以上2點(diǎn)啟示均已在項(xiàng)目?jī)?nèi)落地。
參考文獻(xiàn)
<<分析Go程序的Off-CPU性能>>https://colobu.com/2020/11/12/analyze-On-CPU-in-go/<本期作者
葉性敏
嗶哩嗶哩資深開發(fā)工程師
標(biāo)簽：
