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