葉性敏 嗶哩嗶哩技術 2023-06-02 12:00 發表於上海
本期作者
葉性敏
嗶哩嗶哩資深開發工程師
背景
前段時間同學反映我們活動項目某個服務可用性出現抖動，偶爾低於0.999。雖然看起來3個9的可用性相當高，但是對於一個 10w+ qps 的服務來講，影響面就會被放大到不可接受的狀態。最大的影響就是調用預約接口在流量高峰期有不少超時。預約接口是一個qps相對高的接口，超時就顯得更加嚴重，而且這個問題有一段時間，所以需要儘快排查清楚原因，進行解決。服務可用性監控如下：
這個服務承載了很多活動邏輯，用了很多技術棧如redis,mc,mysql,taishan,es,mongodb,databus等，是一個特大單體。所以業務與組件的複雜給排查問題帶來不少挑戰。
猜想與否定
了解基本情況後，知道可用性降低是由於超時導致，非其他錯誤。進行簡要分析，能夠想出一些可能的原因，例如某些業務寫法導致性能問題，異常流量，系統調用，網絡問題，cpu throttle，中間件問題（如redis,mysql），go調度，gc問題等。至於是這8名嫌疑犯還是另有其人，需要結合實際現象進行排除與論證，所以需要針對性的收集一些線索。
從上圖可以看出，這段時間流量比較規律性，並沒有出現異常波動，似乎這個問題與流量沒什麼直接關係（背景中提到上游反饋尖峰時段超時,可能只是高峰期放大現象），所以排除是異常流量導致的。
可以看出很多接口的999分位都有同樣的問題。如果只是某個業務寫法有問題，僅僅影響該業務的接口。或者可能是業務寫法有問題，影響了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/
- <<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
以上是今天的分享內容，如果你有什麼想法或疑問，歡迎大家在留言區與我們互動，如果喜歡本期內容的話，歡迎點個「在看」吧！