“業務提了個線上問題，麻煩你看一下。”
自從我開始寫 Golang 後端之後，可能是能力有限，我的服務總是會在意想不到的情況下變得異常，而我要做的事情就是解決這個問題。
這次出現的問題看起來是運營平臺後端服務的記憶體洩漏，那就先從記憶體曲線開始看起吧。
突然暴增的曲線
Grafana 平臺給出的曲線大概符合這樣的特徵：有 8 個突變點，每次突變都會讓記憶體猛然上升接近 500 MB，上漲到逼近容器上限後，突然回落到 100 MB（因為容器崩潰重啟了）。
靜態檢查嘗試失敗
結合突變的時間，我搜了一下審計日誌，發現業務上傳了 8 次 Excel。但由於具體的上傳日誌在容器崩潰的時候丟失了，我不得不使用社會工程學透過 PM 直接給業務團隊發訊息拿到 Excel 檔案。
觀察了一下，每個檔案都有著 4w 條記錄，解析完成後恰好佔用了大約 500 MB 記憶體（是的，對於有著大量重複單元格的場景，Excel 的壓縮率超級高，因此幾 MB 的檔案可以被解析出幾百 MB）。但問題來了：為什麼是每次上漲 500 MB，難道是用於儲存解析結果的變數被掛到了全域性或閉包裡？然而查了一下似乎並沒有。
使用 pprof 對比快照
如果靜態分析看不出問題，就要祭出 Golang 最著名的分析工具——pprof 了。但我初來乍到，在 heap / allocs 兩個頁面中研究了好久，並沒有發現有異常。最後搜到了 這篇文章，發現 pprof 可以對兩個快照做 Diff！大概做法如下：
# 一開始先執行
$ curl -s http://127.0.0.1:6060/debug/pprof/heap > base.heap
# 過一段時間，等記憶體增長後再執行
$ curl -s http://127.0.0.1:6060/debug/pprof/heap > current.heap
# 比較兩個快照的差異
$ go tool pprof --base base.heap current.heap然後，透過 pprof 生成了一個 SVG，開啟一看，也沒有問題，甚至部分函式佔用的記憶體變化是負數……我在自己的外星人上面執行服務，瘋狂上傳大檔案，過了幾分鐘後記憶體也恢復到了之前的水平。
MADV_FREE 與 MADV_DONTNEED
經過一番 搜尋，發現從 Golang 1.12 開始，會在 Linux >= 4.5 核心下預設使用 MADV_FREE 來向系統歸還記憶體，而之前的模式是 MADV_DONTNEED。查閱了 Linux manual page 之後，我大概有了些瞭解：
MADV_DONTNEED會在釋放的時候告訴作業系統核心：我不再需要這塊記憶體了。核心雖然會自行決定何時釋放這塊記憶體，但程序的 RSS 一定會立即下降。MADV_FREE標記過的記憶體，則會讓核心在記憶體緊張時才釋放。在釋放之前依舊可以複用。
總的來說，新特性可以加快記憶體釋放的速度，但會造成程序的 RSS 不會立刻下降。這應該是 Golang 的一些考量，但直覺告訴我這可能就是原因。
結合之前學過的一點作業系統基礎，大概可以得出結論：按理說這些記憶體本應可以複用，但當服務執行一段時間後，其中一部分已經被複用了。當業務再次上傳檔案，服務嘗試申請相同大小的記憶體塊時，由於這塊記憶體的可用區域不再滿足需求，系統只能在另一個地方重新分配一塊，這就造成了 RSS 的不斷暴漲。
解決方式有幾種：
- 考慮到運營類平臺對 QPS 要求不高，可以設定
GODEBUG=madvdontneed=1，讓閒置記憶體儘快被系統回收； - 強制單次上傳的最大數量為 1000 條，並在超限時新增提示“最多上傳 1000 條，可以只上傳需要新增或修改的資料”；
- 使用流式 Excel 解析庫，避免一次性分配過大的記憶體。
不過，考慮到這個需求即將下線，且之後短期內不會再有這種量級的檔案上傳需求，因此優先順序不高。最終我們沒有做處理。
為了避免容器意外崩潰後日志丟失，我們做了個技術最佳化，將每次請求的日誌儲存到了檔案服務，之後不管容器是否崩潰，都可以根據時間查到具體的開發日誌，甚至上傳的檔案了。
有借無還再借溢位
“看這曲線，你這容器是不是有記憶體洩漏啊？”這次輪到 SRE 同事來找我了。
確實，SRE 給的圖隨便掃一眼就知道是記憶體洩漏，只不過這次的曲線跟上次相比有個很大的不同——以一個較為緩慢的速度增長。看起來像是每次請求都會保留一些小變數。
這次出問題的服務是我們的資料上報服務。在沒有明確頭緒的情況下，我又打開了 pprof 如法炮製。
對 Gin 的懷疑
這次記憶體佔用的大頭變成了 Golang 的 gzip 包。在我印象中，只有一個地方使用了 gzip：Gin 的請求壓縮，也就意味著可能存在沒有被關閉的 Reader / Writer。於是我跑去 Gin 的 gzip 包裡面找原因，發現它用了一個 Pool，每次先從裡面取一個例項，再設定一些 Gin Response Header，最後把例項的 Writer 接到了 Gin Context。在 #L57 行時執行了 defer gz.Close() 並把例項歸還給 Pool 了，看起來有借有還有關閉，不會造成記憶體洩漏。
既然 Gin 的 gzip 使用沒有問題，難道是 Golang 自己的 gzip 包出問題了？我點進了 Close 函式，發現了 這段程式碼：
func (z *Writer) Close() error {
// ...
if !z.wroteHeader {
z.Write(nil)
if z.err != nil {
return z.err
}
}
z.err = z.compressor.Close()
// ...
}只要 Writer 出了問題就不會 Close，肯定是因為這裡導致的！我在 return 這裡打了斷點，果然，z.err 是這樣的：
http: request method or response status code does not allow body根據錯誤內容看了一下，發現請求方法是 OPTIONS（上報服務肯定會有跨域問題），確實不應該有 Body。
我們為了支援跨域，使用了 gin-contrib/cors 中介軟體，回想到它的原理是發現 OPTIONS 請求後，經過白名單過濾，直接返回結果，而不是繼續往下 c.Next()。那麼為什麼不生效呢？
看了一下注冊中介軟體的程式碼，發現我們把 gzip 的中介軟體放到了第一位，隨後才是 CORS 中介軟體……換一下順序就解決了。
錯誤就能不還了嗎？
那為什麼在出錯的時候 Golang 沒有自動關閉 compressor 呢？看了一下 Golang gzip 包的 Write 方法後，得出了一個原因：多次呼叫 Write 方法時，只要第一次成功，就會有一個開啟的 compressor，如果之後出現了錯誤，Golang 不知道開發者希望如何處理，因此不擅自做決定。如果開發者此時：
- 希望忽略錯誤繼續往裡寫入，可以呼叫
gz.Reset(newWriter)方法，這會保留compressor和level，剩下的欄位全部重置； - 希望就此打住，可以按照 Example 中的寫法直接
panic，也可以先Reset之後再Close。
值得一提的是，Golang 推薦開發者儘可能使用 Reset 複用 gzip 例項，這也許是 Gin gzip 中介軟體使用了 Pool 的原因。
孤獨等待的計時器
隨著資料上報服務的請求量逐漸上漲，SRE 又來找我了，這次依舊是記憶體洩漏問題，並且記憶體曲線也是穩定上升。但這次有點不一樣的是，只有 Live 環境出現了這個情況，而 Test 環境完全沒問題。
不留痕跡的 goroutine 洩露
經歷過前面幾次記憶體溢位的經驗，我總結出了一點：拯救世界，請用 pprof Heap Diff。然而這一次，銀彈失靈了，我沒有從 Heap Diff 中發現任何問題……資料上報服務應該是一個很簡單的服務，不應該有太大的問題才對的。
但是似乎 Golang 分析記憶體問題也沒有其它工具，我不得不重新審視 pprof 提供的功能。在首頁，我發現了當前有數十萬個 goroutine 在執行。這是我之前一直沒有考慮過的點——goroutine 洩漏。
重新回到正常的 Heap Profile 介面，果然發現了一大堆 goroutine 的堆疊，它們不約而同地指向了同一個函式，看起來結論已經很明顯了。我點進這個函式看了一下，才知道為什麼 Diff 沒有任何效果：這個函式自身沒有定義任何新的變數，也沒有生成任何新的字面量，在 Heap 中當然不會留下任何痕跡。
計時器不能隨便停啊
這個函式的功能是批次提交：之前每次接收到的資料會先被放在一個佇列中，然後呼叫這個函式設定一個計時器（如果已有計時器則直接 return），十秒之後把佇列中的資料傳送到一個批次介面中。但為了保證佇列中的內容不會太多，只要超過了 5000 條資料，就會新起一個佇列替換當前佇列，然後直接將替換掉的佇列中的資料批次提交。在 JavaScript 裡面，這個功能很簡單：
let q: ReportData[] = [];
let timerId = 0;
// 接收單個數據，若資料過多則直接提交，否則最多 10s 後提交
const pushBack = (data: ReportData) => {
q.push(data);
if (q.length > 5000) {
flush();
} else {
scheduleFlush();
}
return data;
};
// 設定計時器
const scheduleFlush = () => {
if (timerId) return;
timerId = setTimeout(() => flush(), 10 * 1000);
};
// 真正的提交操作，會清理計時器，並建立一個新佇列
const flush = () => {
setTimeout(() => commit(q));
clearTimeout(timerId);
q = [];
};但是到了 Golang，計時器要用到 time.Ticker，於是我的程式碼成了這樣：
func (q *MemQueue) PushBack(ele interface{}) interface{} {
q.mu.Lock()
defer q.mu.Unlock()
q.queue[q.index].PushBack(ele)
q.len++
if q.len >= 5000 {
q.flush()
} else {
q.scheduleFlush()
}
return ele
}
func (q *MemQueue) scheduleFlush() {
if q.ticker != nil {
return
}
d := time.Duration(10 * int64(time.Second))
q.ticker = time.NewTicker(d)
go func() {
for {
if q.ticker == nil {
return
}
<-q.ticker.C
q.flush()
}
}()
}
func (q *MemQueue) flush() {
go commit(q.queue[q.index])
q.index = 1 - q.index
q.len = 0
q.ticker.Stop()
q.ticker = nil
q.queue[q.index] = list.New()
}之前 Stack 中不約而同指向的位置，就是 scheduleFlush 中的那個 goroutine，它卡在 <-q.ticker.C 這一步，意味著計時器已經停止了。確實，當資料超過 5000 條時會直接呼叫 flush 函式，在停止計時器後，雖然會將 ticker 置空，但由於 <-q.ticker.C 再也收不到資料，因此並不會進行下一輪迴圈。等到下一次資料被推過來時，又會在 scheduleFlush 中啟動一個新的 goroutine。
讓 Channel 來救場
知道了原因，簡單搜了一下，發現了 這個回答，解決方法也就有了：利用一個額外的 Channel 讓迴圈繼續下去。
go func() {
for {
if q.ticker == nil {
return
}
select {
case <-q.forceStop:
return
case <-q.ticker.C:
q.flush()
return
}
}
}()
// 在想停止計時器的地方
q.forceStop <- true
q.ticker.Stop()
q.ticker = nil部署之後發現問題解決。那為什麼只有 Live 環境會出問題，而 Test 環境沒問題呢？因為 flush 函式會在兩個地方被呼叫到——scheduleFlush 和 PushBack。問題出在從 PushBack 直接呼叫 flush 的時候，而這個條件是佇列需要在 10s 內積攢 5000 條資料，Test 環境的 QPS 沒有高到這個程度，所以沒有出現這個問題。
溢位螢幕的 SRE 告警
在那之後的某一天，我直接被 SRE 拉到了他們的告警群裡。群裡最新的訊息是：[error] 11:52 AM ssc k8s pod mem alert 達到 92.60%，在這之前還有五條訊息報的是相同的問題。
我（看了一眼 K8S 面板）：“已知是記憶體洩漏問題，求一個大佬先幫忙臨時重啟一下，我們下次發版後解決。”
似乎不小心給自己立了個 Flag，因為距離下次發版只有兩天了。這次的專案，是本文最開始提到的運營平臺後端服務。
GC 解決不了的問題
這次的記憶體曲線看起來跟一開始的也很類似，會有突然的暴增。我本來以為是：部門發展了一年，請求量大了，業務場景也變多了，可能這次真的需要定時強制釋放記憶體了。於是加了個定時器：
func freeMemory(r *registry.Registry) {
debug.FreeOSMemory()
r.BasicLogger.Info("free-memory", "Free memory successful")
}
c := cron.New()
c.AddJob("@every 10m", &freeMemoryJob{
f: freeMemory,
})
c.Start()然後發現曲線長成了這樣：
只能用一句話來表達此時的感受：氣哭.jpg。當時後端出身的老闆剛好經過我工位，希望他沒有看到這張圖吧。
圖中之所以每小時有一個峰值，因為我們有一個按小時執行的計劃任務，可能會佔用一些記憶體；之所以後來下降了好多，是因為我重新部署了……
全域性 map 要慎用
行吧，應該還是有什麼小型變數忘了釋放。我故技重施，打開了 pprof。
憑藉我對自己程式碼的瞭解，我知道這一部分的需求是什麼：就是在解決一開始的問題時提出的技術最佳化——將開發日誌儲存到檔案服務。對於一個請求，如何收集貫穿整個服務的開發日誌呢？一個比較容易想到的方法是設定一個全域性變數 map[string][]string，也就是 Trace ID 到該請求的日誌列表的對映。在請求的過程中可以隨時往裡面新增日誌，請求結束後透過中介軟體將日誌列表中的內容儲存到檔案服務，然後刪除掉這個 Trace ID 對應的資料。
一切看起來天衣無縫——每個請求不管過程和結果如何，最終 map 中的內容一定會被刪除，但這個曲線看起來就跟沒有被刪除一樣。以前之所以沒有出過這個問題，是因為以前打的日誌量比較少，記憶體增長不明顯。現在日誌量大了，就出現了這個問題。
迫於 SRE 大佬的壓力，我透過不斷將 golang map delete memory leak 這幾個詞語排列組合搜尋，也去看了一下 map 的實現，參考了 這篇文章，發現了這樣一個問題：Golang 的 map 在刪除 Key 的時候，只會把 Key 標記為 empty，而不是徹底刪除，這樣在下一次插入相同的 Key 時就可以節約一些時間。考慮到 map 用的是雜湊表，經常的擴縮容確實對效能有影響，這種設計看起來還算合理。
但是我這個使用場景有個嚴重的問題：我的 Key 是 Trace ID，也就意味著幾乎沒有重複的可能，幾乎所有的值都會被保留下來。以前的 QPS 很低，日誌量也少，於是這個問題沒有那麼明顯；現在有些計劃任務動輒上千條日誌，這個問題就被放大了。
如何解決呢？其實也很簡單，只要去掉全域性的 map，使用中介軟體在每一個 Gin Context 中生成一個新的 logger，最後只上傳這個 logger 的內容就可以了。此外，由於在這段時間裡，公司的 Infra 團隊自研了一套日誌平臺，我也毫不猶豫地接了進去，之後日誌就不用儲存到檔案服務了。
運行了一段時間，看監控可以發現，記憶體洩漏已經解決了；用 pprof Diff 了一下，發現已經沒有被標紅的函式，甚至有一些函式被標綠了，意味著這些函式佔用的記憶體下降了。
之所以一開始記憶體還有上漲的跡象，是因為這個服務為了效率而快取了訪問的使用者資料。資料量最多隻有幾萬，對記憶體沒有什麼壓力。
小結
經過這一段時間與記憶體洩漏的鬥爭被完虐，我發現自己似乎把常見的記憶體洩漏問題都遇到了一遍，也算是積累了一些經驗。我不確定現在的專案是否還有潛在的記憶體洩漏風險，但我已經有足夠的信心來解決不管是未知還是已知的問題了。