一次 Go 程式 out of memory 排查及反思

2021 年 5 月 11 日
筆記
Go, 後端開發

前言

最近在搞數據導出模組，在測試大文件下載的過程中，報了 Out of memory (OOM) 錯誤，因為之前沒有遇到過這類問題，導致此次排查問題花費了大半天，也走了不少彎路，特此復盤記錄。

現象描述

和往常一樣複製粘貼完最後一個下載介面，沒什麼問題的話，導出模組就可以收工了。

上伺服器部署完，隨便測試了幾個小文件的下載，一切按照預期正常地運行。

隨後我點擊下載了一個 2.6G 的大文件，情況變得糟糕起來，通過 docker stats 觀察到其記憶體一直上漲到 7G 左右，然後容器 Exit 2，日誌報 fatal error: runtime: out of memory。

此時我一點都不緊張，甚至有點高興，剛好這幾天在看 pprof，並且平時 curd 干多了，正好來點 bug 調解一下心情~

排查過程

現場日誌

fatal error: runtime: out of memory

runtime stack:
runtime.throw(0x1447dc3, 0x16)
        runtime/panic.go:774 +0x72
runtime.sysMap(0xc13c000000, 0x130000000, 0x3202418)
        runtime/mem_linux.go:169 +0xc5
runtime.(*mheap).sysAlloc(0x31e12c0, 0x130000000, 0x7f4cfdffaae8, 0x43d067)
        runtime/malloc.go:701 +0x1cd
runtime.(*mheap).grow(0x31e12c0, 0x98000, 0xffffffff)
        runtime/mheap.go:1255 +0xa3
runtime.(*mheap).allocSpanLocked(0x31e12c0, 0x98000, 0x3202428, 0x7f4c00000000)
        runtime/mheap.go:1170 +0x266
runtime.(*mheap).alloc_m(0x31e12c0, 0x98000, 0x101, 0x7f4cfdffac08)
        runtime/mheap.go:1022 +0xc2
runtime.(*mheap).alloc.func1()
        runtime/mheap.go:1093 +0x4c
runtime.(*mheap).alloc(0x31e12c0, 0x98000, 0x7f4cfd010101, 0x43e155)
        runtime/mheap.go:1092 +0x8a
runtime.largeAlloc(0x12fffff10, 0xc000040101, 0xc001816180)
        runtime/malloc.go:1138 +0x97
runtime.mallocgc.func1()
        runtime/malloc.go:1033 +0x46
runtime.systemstack(0xc001d80180)
        runtime/asm_amd64.s:370 +0x66
runtime.mstart()                                       
        runtime/proc.go:1146

由於 go panic 時，將所有的 goroutine 調用棧都列印了出來，報錯資訊鋪了好幾頁，而且第一行是一個 runtime error，所以當時我就粗略地看了一下，並沒有找到什麼有用日誌。

分析程式碼

// file download
filePath := path.Join(ms.Configs().GetString("system.exportPath"), filename)

f, _ := os.Open(filePath)
defer f.Close()
stat, _ := f.Stat()

c.Writer.WriteHeader(http.StatusOK)
c.Header("Content-Disposition", "attachment; filename="+filename)
c.Header("Content-Type", "application/octet-stream")
c.Header("Content-Length", fmt.Sprintf("%d", stat.Size()))
c.File(filePath)

核心程式碼就這麼幾行，而且還是從老項目中複製過來的，怎麼可能出問題？？？

此時我的內心開始甩鍋了，可能是環境的問題？老項目用的是 k8s，現在用的是 docker-compose、老項目用的是 go1.13 現在是 go1.15。

demo測試

由於項目依賴較多，本地運行不太方便，於是我寫了一個小 demo，打算不用 docker 直接跑起來（準備把鍋甩給 docker）

func main() {
	r := gin.Default()
	r.GET("/download", func(c *gin.Context) {
		filename := "cb6mp2mh843u.zip"
		filePath := path.Join("/data", filename)
		c.Writer.WriteHeader(http.StatusOK)
		c.Header("Content-Disposition", "attachment; filename="+filename)
		c.Header("Content-Type", "application/octet-stream")
		c.File(filePath)
	})
	r.Run("0.0.0.0:8686")
}

demo 跑起來後，多次測試，記憶體使用情況一切正常，此時我陷入了沉思……

pprof

沒辦法，只好用 pprof 了，剛好現學現用。

使用 pprof 採集了 heap 的數據，很快就找到了問題，項目使用的小組內基於 gin 封裝的一個輪子，為了記錄 response body 日誌，將其 Dump 了下來，2.6G 的數據呀…

於是我順手加了個 if else 判斷，修了這個 bug

復盤反思

所以當時我就粗略地看了一下，並沒有找到什麼有用日誌

程式出錯時報的日誌，裡面包含了最重要，直接的排查線索，一定要仔細地將每一行都看一遍，不能由於資訊較多，就忽略它。

事後統計當時報錯的日誌就 300 多行，12 個 goroutine，如果稍微仔細看一下，我相信很快就能定位到問題所在，也不用水這一篇文章了。

可能是環境的問題？老項目用的是 k8s，現在用的是 docker-compose、老項目用的是 go1.13 現在是 go1.15

在出現問題時，程式設計師總是喜歡將鍋甩給環境、工具等，不是說這些基礎組件一定沒有 bug，而是對於大多數的 CRUD 程式來說，根本觸發不了底層組件的問題。

所以當沒有十足的證據來表明是基礎組件的問題時，我們還是老老實實地分析自己的程式碼，別把路走偏了。

由於項目依賴較多，本地運行不太方便，於是我寫了一個小 demo

在寫 demo 時，一定要注意單一變數原則，項目中使用了組內基於 gin 封裝的一個小輪子，而 demo 中使用的是原生的 gin，最難受的是，最終排查到是小輪子的 bug。

Tags: Go 後端開發