背景

前段時間同學(xué)反映我們活動項(xiàng)目某個服務(wù)可用性出現(xiàn)抖動，偶爾低于0.999。雖然看起來3個9的可用性相當(dāng)高，但是對于一個 10w+ qps 的服務(wù)來講，影響面就會被放大到不可接受的狀態(tài)。最大的影響就是調(diào)用預(yù)約接口在流量高峰期有不少超時。預(yù)約接口是一個qps相對高的接口，超時就顯得更加嚴(yán)重，而且這個問題有一段時間，所以需要盡快排查清楚原因，進(jìn)行解決。服務(wù)可用性監(jiān)控如下：

這個服務(wù)承載了很多活動邏輯，用了很多技術(shù)棧如redis,mc,mysql,taishan,es,mongodb,databus等，是一個特大單體。所以業(yè)務(wù)與組件的復(fù)雜給排查問題帶來不少挑戰(zhàn)。

猜想與否定

了解基本情況后，知道可用性降低是由于超時導(dǎo)致，非其他錯誤。進(jìn)行簡要分析，能夠想出一些可能的原因，例如某些業(yè)務(wù)寫法導(dǎo)致性能問題，異常流量，系統(tǒng)調(diào)用，網(wǎng)絡(luò)問題，cpu throttle，中間件問題（如redis,mysql），go調(diào)度，gc問題等。至于是這8名嫌疑犯還是另有其人，需要結(jié)合實(shí)際現(xiàn)象進(jìn)行排除與論證，所以需要針對性的收集一些線索。

從上圖可以看出，這段時間流量比較規(guī)律性，并沒有出現(xiàn)異常波動，似乎這個問題與流量沒什么直接關(guān)系（背景中提到上游反饋高峰時段超時,可能只是高峰期放大現(xiàn)象），所以排除是異常流量導(dǎo)致的。

可以看出很多接口的999分位都有同樣的問題。如果只是某個業(yè)務(wù)寫法有問題，僅僅影響該業(yè)務(wù)的接口?；蛘呖赡苁菢I(yè)務(wù)寫法有問題，影響了runtime，那就具體再看runtime的表現(xiàn)，所以當(dāng)時并沒有深入看業(yè)務(wù)代碼。

其實(shí)cpu throttle并不高，也問過運(yùn)維，沒啥異常，不太像是導(dǎo)致超時的原因。中間有個小插曲：當(dāng)時有同學(xué)從cpu throttle導(dǎo)致超時這個猜想出發(fā)，發(fā)現(xiàn)預(yù)約業(yè)務(wù)內(nèi)存cache占用量比較大（占用大的話可能影響內(nèi)存的分配與釋放），嘗試減少預(yù)約業(yè)務(wù)內(nèi)存cache占用量。觀察一段時間，cpu throttle稍微有點(diǎn)降低，但可用性問題依然沒有好轉(zhuǎn)。

后續(xù)通過查看trace，發(fā)現(xiàn)那段時間mysql與redis均有超時，細(xì)看給mysql的查詢時間只有0.01ms，mysql說這鍋我不背的。

那redis層呢，給了21.45ms，似乎給比較充足的查詢時間，且redis有毛刺（不過毛刺時間點(diǎn)與可用性抖動點(diǎn)對不上），但是redis內(nèi)心一萬個不服啊。那行我們找對應(yīng)時間段，再多看幾個超時請求的trace，發(fā)現(xiàn)這些請求給redis的查詢時間都比較短，如下圖：

好吧，redis也可以鼓起勇氣說，這鍋我也不背。

其他組件也同樣看過，都沒啥異常。那么問題來了，組件們都不背，那到底誰來背？那網(wǎng)絡(luò)，系統(tǒng)調(diào)用，go調(diào)度與gc，你們自己看著辦吧。

網(wǎng)絡(luò)說你再仔細(xì)想想，不對啊，一個請求至少給了250ms的time_quota，你們最后只留給我和組件們那么點(diǎn)時間，redis 0.04ms，mysql 0.01ms。請問扣除這點(diǎn)時間，剩余是誰“消費(fèi)”了，應(yīng)該心知肚明了吧。說到這，go調(diào)度，系統(tǒng)調(diào)用與gc主動跳出來了。

排查思路

現(xiàn)在的矛頭指向go runtime與系統(tǒng)調(diào)用。根據(jù)以往的經(jīng)驗(yàn)有以下幾種主要手段輔助定位：

1. 采集pprof，用cpu profiler查看cpu占用，memory profiler查看gc問題
2. 開啟GODEBUG=gctrace=1 ，可查看程序運(yùn)行過程中的GC信息。如果覺得是gc問題，可查看服務(wù)可用性抖動時間段gctrace是否異常，進(jìn)一步確認(rèn)問題
3. 添加fgprof，輔助排查off-cpu可能性，off-cpu例如I/O、鎖、計時器、頁交換等，具體詳看鳥窩大佬文章：分析Go程序的Off-CPU性能（https://colobu.com/2020/11/12/analyze-On-CPU-in-go/）
4. 采集go trace，查看go調(diào)度問題，例如gc、搶占調(diào)度等，真實(shí)反映當(dāng)時調(diào)度情況
5. linux strace查看go運(yùn)行時調(diào)用了哪些系統(tǒng)調(diào)用導(dǎo)致超時

分析

gctrace分析

根據(jù)以往一些經(jīng)驗(yàn)，gc有時候會影響系統(tǒng)的延時，所以先用gctrace看看這塊有沒有問題。

從gctrace上可以看出，并發(fā)標(biāo)記和掃描的時間占用了860ms（圖中紅色框0.8+860+0.0668 ms中的860，一般gc問題通常看這塊區(qū)域），并發(fā)標(biāo)記和掃描比較占用cpu時間，這樣可能導(dǎo)致這段時間大多數(shù)cpu時間用于掃描，業(yè)務(wù)協(xié)程只能延遲被調(diào)度。后續(xù)與可用性未抖動時間段的gctrace對比，發(fā)現(xiàn)并發(fā)標(biāo)記與掃描時間并沒有明顯增多，但從860ms的時長上看，感覺也不是很合理，但沒有證據(jù)證明它就能夠?qū)е鲁瑫r抖動，這塊異常先記著。

 strace分析

并未發(fā)現(xiàn)異常，都是一些正常的系統(tǒng)調(diào)用，看不出有明顯系統(tǒng)導(dǎo)致goroutine超時，所以"系統(tǒng)調(diào)用"這個嫌疑也暫時排除。

fgprof分析

未見異常，結(jié)論同strace一樣，未出現(xiàn)off-cpu的協(xié)程堵塞。

 go trace分析

嘗試多次(超過20次)抓取go trace文件進(jìn)行分析。從trace文件上，可以明顯看到發(fā)生MARK ASSIST了，頓時心中有譜。多抓trace看看，還是有明顯的MARK ASSIST了現(xiàn)象，gc問題應(yīng)該比較明顯了。

go heap 分析

如果是gc問題，那就和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。這塊明顯有問題，那很可能就是它導(dǎo)致的問題。

解決

我們找到最大的嫌疑-gcache（該包引入項(xiàng)目已一年多）?？戳艘幌聵I(yè)務(wù)中使用gcache的情況及LFU的使用處

從用法上，未發(fā)現(xiàn)有什么問題。便把問題轉(zhuǎn)向gcache包本身。百度，google一頓搜索，源碼淺看了一下，也沒發(fā)現(xiàn)異常。github.com issue一搜，發(fā)現(xiàn)有人提過類似問題https://github.com/bluele/gcache/issues/71。gcache LFU策略的Get方法存在內(nèi)存泄露（內(nèi)存大概泄露100M，占總內(nèi)存占用量2.5%，主要是產(chǎn)生大量指針對象）。具體bug是如何產(chǎn)生的，由于篇幅原因，這里不進(jìn)行贅述，可參考issue（https://github.com/bluele/gcache/issues/71）。后續(xù)將gcahce版本從v0.0.1升級至v0.0.2，該問題得以解決。

gcache竟然是你啊，偷走了我0.001的服務(wù)可用性。

總結(jié)

至此問題排查與解決都告一段落了，但有些問題還需總結(jié)與復(fù)盤。

從上面看，你可能想這問題好像也很容易就排查到了，實(shí)際排查過程中并不順利。在進(jìn)行trace及heap分析時也是抓取了很多次，才抓到有效信息。后面發(fā)現(xiàn)某些gcache的過期時間只有5分鐘，過了這5分鐘，現(xiàn)場就沒了（如果能有自動抓取能力，那該多方便），這讓懷疑是gc問題的我們一段時間在自我肯定與否定中。中間產(chǎn)生更多猜想，例如懷疑定時器使用過多(業(yè)務(wù)代碼里面比較多后臺刷新配置的定時器)，導(dǎo)致業(yè)務(wù)邏輯調(diào)度延遲；grpc客戶端連接過多(2w+)，占用較大內(nèi)存，產(chǎn)生較多對象，影響gc；也有猜測是機(jī)器問題；常駐內(nèi)存cache過多，內(nèi)部指針較多，影響gc掃描；甚至想用go ballast 絲滑的控制內(nèi)存等。

關(guān)于系統(tǒng)穩(wěn)定性這塊的小啟示：

1. 第三方庫的引入還需慎重。本次問題是第三方包bug導(dǎo)致的，所以引入包時需要考慮合理性，避免引入不穩(wěn)定因素。第三方包的安全漏洞問題大家一般比較重視，bug卻常常被忽視?？芍贫ǖ谌桨囊霕?biāo)準(zhǔn)、編寫工具監(jiān)測第三方包issue的提出與解決，通知開發(fā)人員評估風(fēng)險及更新包版本，從而做到第三方包的合理引入，快速發(fā)現(xiàn)issue以及修復(fù)。
2. 關(guān)于系統(tǒng)穩(wěn)定性這塊，基本上都是盡可能的添加監(jiān)控(包括系統(tǒng)，組件，go runtime維度)，通過報警及時發(fā)現(xiàn)問題或隱患。至于go程序運(yùn)行時內(nèi)部的現(xiàn)場？似乎只能出問題時在容器內(nèi)部或者借助公司自研平臺手動抓取pprof，但多少存在一定的滯后性，有時候甚至現(xiàn)場都沒了。當(dāng)然也有人定時抓取pprof，但多少有點(diǎn)影響性能，姿勢也不夠優(yōu)雅。holmes(MOSN 社區(qū)性能分析利器)就顯得很有必要。通過相應(yīng)的策略，例如協(xié)程暴漲，cpu異常升高，內(nèi)存OOM等情況，自動抓取，達(dá)到近似"無人值守"。既能夠較好的保留事故現(xiàn)場，也能提前暴漏一些隱患。

以上2點(diǎn)啟示均已在項(xiàng)目內(nèi)落地。

參考文獻(xiàn)

• <<分析Go程序的Off-CPU性能>> https://colobu.com/2020/11/12/analyze-On-CPU-in-go/
• <<Holmes 原理淺析>> https://mosn.io/blog/posts/mosn-holmes-design/
• holmes github：https://github.com/mosn/holmes
• gcache github: https://github.com/bluele/gcache
• <<深度解密Go語言之 pprof>> https://www.cnblogs.com/qcrao-2018/p/11832732.html

本期作者

葉性敏

嗶哩嗶哩資深開發(fā)工程師