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