記一次線上Giao(go)服務內存佔用率太高問題排查

本文做者： 保護我方李元芳
商業轉載請聯繫做者得到受權，非商業轉載請註明出處。

故障現象

某線上埋點上報機器偶爾觸發內存佔用過多的報警。ssh到機器top發現主要內存被埋點服務佔用。以前重啓過幾回，可是過段時間仍然會發生內存佔用過多的警報。下面是報警詳情。

[P1][PROBLEM][ali-e-xxx-service03.bj][][ all(#3) mem.memfree.percent 4.19575<5][O3 >2019-10-28 10:20:00]

問題推斷

埋點服務主要接收客戶端壓縮過的上報請求，並對請求數據作解壓，投遞到kafka，邏輯功能相對簡單。初步懷疑是某些資源沒有釋放致使的內存泄露或Groutine泄露。

問題排查

因爲代碼不是由咱們業務方維護的，首先向相關部門索要了代碼權限。閱讀了一下源碼，全部資源釋放都是由defer進行操做的，並無發現很明顯的資源未釋放的狀況。

1. 修改線上環境配置，打開trace端口

在調試分析問題以前，熟悉go的同窗都知道Golang 提供了很是方便的性能診斷工具 go tool trace; go tool trace是golang中的性能大殺器， 能揭露運行中的全部的運行時事件和內存佔用等。 它是Go生態系統中用於診斷性能問題時（如延遲，並行化和競爭異常）最有用的工具之一。

因爲都是採用公司的基礎庫，基礎庫專門對go trace作了封裝。只須要在線上機器修改config文件，將trace信息發送到配置文件中的指定端口就可使用go tool進行分析了。

而後我在本地進行使用go tool 工具發現網絡不通，排查了一下發現trace端口沒有綁定到0.0.0.0上[狗頭]。 隨即用proxy工具將 9900 端口反向代理到9999端口，而後使用go tool對正常狀態的內存佔用作了一個內存火焰圖。以下圖 2020-01-18-18-11-23.jpg

2. 等待故障發生

等待是個很漫長的過程，可能須要幾天或者運氣很差的話個把月。此處省去幾萬字 x#@#@$@^!。。。

3. 該來的總歸仍是來了

過了幾天後又收到了服務器警報，因爲qps上升，此次比前幾回來的都早一些。接到警報後當即對內存作了一個top

go tool pprof -alloc_space http://{addr}/debug/pprof/heap
複製代碼

Showing top 20 nodes out of 55
      flat  flat%   sum%        cum   cum%
    2.76GB 59.76% 59.76%     2.76GB 59.76%  compress/flate.NewReader
    0.45GB  9.73% 69.49%      0.45GB  9.73%  net/http.newBufioWriterSize
    0.29GB  6.33% 75.82%     3.05GB 66.09%  compress/gzip.(*Reader).Reset
    0.25GB  5.35% 81.17%     0.25GB  5.35%  net/http.newBufioReader
    0.13GB  2.85% 84.01%     0.13GB  2.85%  runtime.rawstringtmp
    0.11GB  2.31% 86.32%     0.11GB  2.31%  bytes.makeSlice
    0.10GB  2.26% 88.58%     0.10GB  2.26%  runtime.hashGrow
複製代碼

每一行表示一個函數的信息。前兩列表示函數使用內存以及百分比；第三列是當前全部函數累加使用 Memory 的比例；第四列和第五列表明這個函數以及子函數運行所佔用的Memory和比例（也被稱爲累加值 cumulative），應該大於等於前兩列的值；最後一列就是函數的名字。若是應用程序有性能問題，上面這些信息應該能告訴咱們內存都花費在哪些函數的執行上了，另外pprof的CPU時間分析也相似。

pprof 不只能打印出最耗內存的的地方(top)，還能列出函數代碼以及對應的取樣數據(list)、彙編代碼以及對應的取樣數據(disasm)，並且能以各類樣式進行輸出，好比 svg、gv、callgrind、png、gif等等。

能夠看到的是大部份內存都被這些Reader佔用了.

4. 帶着問題從新閱讀代碼

前面咱們進行了佔用的初步分析，找到了內存佔用多的Fcuntion是flate.NewReader,Package flate 實現了 RFC 1951 中描述的 DEFLATE 壓縮數據格式, gzip 包實現了對基於 DEFLATE 的文件格式的訪問。因此咱們帶着問題咱們再次定位到相關源碼實現，下面是一些關鍵定義:

var Gzip GzipPool
func GetReader(src io.Reader) (*gzip.Reader, error) {
	return Gzip.GetReader(src)
}

func PutReader(reader *gzip.Reader) {
	Gzip.PutReader(reader)
}

// GzipPool manages a pool of gzip.Writer.
// The pool uses sync.Pool internally.
type GzipPool struct {
	readers sync.Pool
	writers sync.Pool
}
複製代碼

這裏用到了sync.Pool 來優化GC, 爲了驗證內存都在pool上，咱們又使用go tool 提供的web工具對查看了一下pool的內存佔用，果真大部分佔用都在pool上。時間久遠此次沒圖了。。。

5. 什麼是 sync.Pool ?

sync包提供了基礎的golang併發編程工具。根據官方文檔的描述:

Pool's purpose is to cache allocated but unused items for later reuse, relieving pressure on the garbage collector. That is, it makes it easy to build efficient, thread-safe free lists. However, it is not suitable for all free lists.

咱們一般用golang來構建高併發場景下的應用，可是因爲golang內建的GC機制會影響應用的性能，爲了減小GC，golang提供了對象重用的機制，也就是sync.Pool對象池。 sync.Pool是可伸縮的，併發安全的。其大小僅受限於內存的大小，能夠被看做是一個存放可重用對象的值的容器。 設計的目的是存放已經分配的可是暫時不用的對象，在須要用到的時候直接從pool中取。看到這裏相信許多熟悉GC的同窗內心已經有答案的猜想了: 或許和GC有關。

So，Golang的GC觸發時機是什麼？

Golang GC1.13版本的GC實現是三色標記發配合寫屏障和輔助GC。觸發條件主要有兩個:

1. 超過內存大小閾值
2. 達到定時時間

閾值是由一個gcpercent的變量控制的,當新分配的內存佔已在使用中的內存的比例超過gcprecent時就會觸發。 好比一次回收完畢後，內存的使用量爲5M，那麼下次回收的時機則是內存分配達到10M的時候。也就是說，並非內存分配越多，垃圾回收頻率越高。 若是一直達不到內存大小的閾值呢？這個時候GC就會被定時時間觸發，好比一直達不到10M，那就定時（默認2min觸發一次）觸發一次GC保證資源的回收。

因此咱們當內存佔用慢慢升高的時候，gc觸發次數會減小而且趨近於2min，沒有gc就不會對pool中對象進行回收，致使內存佔用率逐漸升高。

主動觸發GC進行驗證

修改代碼，限制rlimit，並使用一個goroutine 每30s主動調用gc，而後進行測試後上線。觀測線上接口耗時並未發生明顯變化，系統運行正常，內存佔用報警再也沒有被觸發過。

問題總結

剛開始對偶爾觸發的內存報警並無過多的在乎，有許多僥倖心理，但問題總歸是客觀存在的，及時發現問題，定時總結才能不斷進步成長，儘可能避免一有問題就重啓，防止成爲SRB(Service ReBoot Boy😁).

---

參考文檔

[1] golang 內存分析/動態追蹤
[2] golang GC