記一次Golang內存分析——基於go pprof

1. 背景

阿里雲Redis線上在某些任務流中使用redis-port來進行實例之間的數據同步。redis-port是一個MIT協議的開源軟件，主要原理是從源實例讀取RDB快照文件、解析、然后在目標實例上應用灌數據的寫命令。為了限制每個進程的最大內存使用，我們使用cgroup來做隔離，最近線上出現redis-port在同步數據時OOM的情況，最高內存使用達到了10G以上，而實際RDB的大小只有4.5GB左右。

2. 分析

2.1 GCTRACE

Golang，自帶gc，在不改動代碼的情況下，我們可以設置GODEBUG='gctrace=1'環境變量啟動程序，來向標准錯誤輸出打印gc log，

gc 21 @8.389s 0%: 0.069+4.0+0.16 ms clock, 1.6+2.8/14/10+4.0 ms cpu, 87->88->45 MB, 89 MB goal, 24 P gc 22 @8.919s 0%: 0.053+3.7+0.63 ms clock, 1.0+1.9/16/12+12 ms cpu, 87->88->44 MB, 90 MB goal, 24 P gc 23 @9.431s 0%: 0.055+3.9+0.18 ms clock, 1.3+2.6/15/13+4.5 ms cpu, 87->88->45 MB, 89 MB goal, 24 P gc 24 @9.948s 0%: 0.093+6.0+1.1 ms clock, 2.2+2.3/18/5.6+27 ms cpu, 87->88->44 MB, 90 MB goal, 24 P gc 25 @10.108s 0%: 0.026+10+0.55 ms clock, 0.63+0/12/15+13 ms cpu, 88->89->66 MB, 89 MB goal, 24 P gc 26 @10.407s 0%: 0.023+23+0.57 ms clock, 0.56+0/41/3.3+13 ms cpu, 178->178->133 MB, 179 MB goal, 24 P gc 27 @10.792s 0%: 0.024+45+0.58 ms clock, 0.58+0/63/2.5+14 ms cpu, 282->282->222 MB, 283 MB goal, 24 P gc 28 @11.560s 0%: 0.023+92+0.13 ms clock, 0.55+0/17/100+3.1 ms cpu, 520->520->399 MB, 521 MB goal, 24 P gc 29 @13.113s 0%: 0.035+186+0.53 ms clock, 0.85+0/21/187+12 ms cpu, 997->997->755 MB, 998 MB goal, 24 P gc 30 @14.490s 0%: 0.035+9.2+0.55 ms clock, 0.84+0.20/18/3.0+13 ms cpu, 858->858->518 MB, 1510 MB goal, 24 P gc 31 @16.208s 0%: 0.032+381+0.15 ms clock, 0.77+0/400/3.5+3.7 ms cpu, 1610->1610->1466 MB, 1611 MB goal, 24 P gc 32 @16.841s 0%: 0.024+9.6+0.12 ms clock, 0.59+0.12/15/6.7+3.0 ms cpu, 1488->1489->993 MB, 2932 MB goal, 24 P gc 33 @22.381s 0%: 0.026+752+0.14 ms clock, 0.64+0/18/760+3.3 ms cpu, 3358->3359->2888 MB, 3359 MB goal, 24 P gc 34 @23.237s 0%: 0.020+7.7+0.12 ms clock, 0.49+0.14/17/2.0+2.9 ms cpu, 2889->2889->1940 MB, 5776 MB goal, 24 P gc 35 @34.475s 0%: 0.032+9.9+0.11 ms clock, 0.77+0.65/17/9.3+2.7 ms cpu, 2910->2910->1940 MB, 3881 MB goal, 24 P gc 36 @34.732s 0%: 0.025+1412+0.13 ms clock, 0.60+0/1422/10+3.2 ms cpu, 5746->5746->5732 MB, 5747 MB goal, 24 P gc 37 @54.129s 0%: 0.028+9.9+0.12 ms clock, 0.67+0.95/18/11+3.0 ms cpu, 7274->7274->3836 MB, 11464 MB goal, 24 P gc 38 @59.297s 0%: 0.032+2910+0.13 ms clock, 0.78+0/2920/13+3.2 ms cpu, 11847->11847->11420 MB, 11848 MB goal, 24 P gc 39 @64.199s 02010.046+29024+0.32 ms clock, 1.1+0/18/3195+7.7 ms cpu, 15532->15532->11577 MB, 22840 MB goal, 24 P

上面是部分gc log，gc后面的數字表示是第幾次gc，@后面的數字表示程序啟動經歷的時間，后面幾項和gc消耗的cpu時間有關，在分析gc導致的程序hang時很有用，但是不是我們這次關注的重點，主要看下倒數第2和第3項

#->#-># MB heap size at GC start, at GC end, and live heap # MB goal goal heap size (這個解釋一下，每次gc circle完，gc會根據當前分配的堆內存大小和GOGC環境變量，計算下一次gc的目標內存大小，如果后面內存使用沒有超過這個goal，gc不會用力太猛)

從這個gc log我們可以看到從某個時間點開始，內存使用開始猛增，gc基本沒有回收多少內存，看了下源實例的key情況，主要是string類型和hash類型，而且hash類型存在大key（一個hash有2800w的member，不過不建議大家這么使用，盡量打散到單個hash 10w以內），所以這里懷疑是先從RDB讀了一部分string，然后讀到大key的時候內存突增。有了方向，要確認詳細原因，就要祭出大殺器Golang pprof了。

2.2 Golang pprof

分析內存使用要是光擼代碼還是比較困難的，總要借助一些工具。Golang pprof是Golang官方的profiling工具，非常強大，使用也比較方便。

我們在程序中嵌入如下幾行代碼，

import _ "net/http/pprof" go func() { http.ListenAndServe("0.0.0.0:8899", nil) }()

在瀏覽器中輸入http://ip:8899/debug/pprof/可以看到一個匯總頁面，

/debug/pprof/ profiles: 0 block 32 goroutine 552 heap 0 mutex 51 threadcreate full goroutine stack dump

其中heap項是我們需要關注的信息，

heap profile: 96: 1582948832 [21847: 15682528480] @ heap/1048576
91: 1527472128 [246: 4129210368] @ 0x471d87 0x471611 0x4718cd 0x4689bf 0x50deb9 0x50d7ac 0x75893b 0x45d801 # 0x471d86 bytes.makeSlice+0x76 /usr/local/go/src/bytes/buffer.go:231 # 0x471610 bytes.(*Buffer).grow+0x140 /usr/local/go/src/bytes/buffer.go:133 # 0x4718cc bytes.(*Buffer).Write+0xdc /usr/local/go/src/bytes/buffer.go:163 # 0x4689be io.(*multiWriter).Write+0x8e /usr/local/go/src/io/multi.go:60 # 0x50deb8 github.com/CodisLabs/redis-port/pkg/rdb.createValueDump+0x198 go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/loader.go:194 # 0x50d7ab github.com/CodisLabs/redis-port/pkg/rdb.(*Loader).NextBinEntry+0x28b go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/loader.go:176 # 0x75893a main.newRDBLoader.func1+0x23a go_workspace/src/github.com/CodisLabs/redis-port/cmd/utils.go:733 ......

包括一些匯總信息，和各個go routine的內存開銷，不過這里除了第一行信息比較直觀，其他的信息太離散。可以看到當前使用的堆內存是1.58GB，總共分配過15.6GB。

heap profile: 96(inused_objects): 1582948832(inused_bytes) [21847(allocated_objects): 15682528480(allocted_bytes)] @ heap/1048576

更有用的信息我們需要借助go tool pprof來進行分析，

go tool pprof -alloc_space/-inuse_space http://ip:8899/debug/pprof/heap

這里有兩個選項，-alloc_space和-inuse_space，從名字應該能看出二者的區別，不過條件允許的話，我們優先使用-inuse_space來分析，因為直接分析導致問題的現場比分析歷史數據肯定要直觀的多，一個函數alloc_space多不一定就代表它會導致進程的RSS高，因為我們比較幸運可以在線下復現這個OOM的場景，所以直接用-inuse_space。

這個命令進入后，是一個類似gdb的交互式界面，輸入top命令可以前10大的內存分配，flat是堆棧中當前層的inuse內存值，cum是堆棧中本層級的累計inuse內存值（包括調用的函數的inuse內存值，上面的層級），

(pprof) top
Showing nodes accounting for 3.73GB, 99.78% of 3.74GB total Dropped 5 nodes (cum <= 0.02GB) Showing top 10 nodes out of 16 flat flat% sum% cum cum% 3.70GB 98.94% 98.94% 3.70GB 98.94% bytes.makeSlice /usr/local/go/src/bytes/buffer.go 0.03GB 0.83% 99.78% 0.03GB 0.83% main.(*cmdRestore).Main /usr/local/go/src/bufio/bufio.go 0 0% 99.78% 3.70GB 98.94% bytes.(*Buffer).Write /usr/local/go/src/bytes/buffer.go 0 0% 99.78% 3.70GB 98.94% bytes.(*Buffer).grow /usr/local/go/src/bytes/buffer.go 0 0% 99.78% 3.70GB 98.94% github.com/CodisLabs/redis-port/pkg/rdb.(*Loader).NextBinEntry go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/loader.go 0 0% 99.78% 3.70GB 98.94% github.com/CodisLabs/redis-port/pkg/rdb.(*rdbReader).Read go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/reader.go 0 0% 99.78% 3.70GB 98.94% github.com/CodisLabs/redis-port/pkg/rdb.(*rdbReader).ReadBytes go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/reader.go 0 0% 99.78% 3.70GB 98.94% github.com/CodisLabs/redis-port/pkg/rdb.(*rdbReader).ReadString go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/reader.go 0 0% 99.78% 3.70GB 98.94% github.com/CodisLabs/redis-port/pkg/rdb.(*rdbReader).readFull go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/reader.go 0 0% 99.78% 3.70GB 98.94% github.com/CodisLabs/redis-port/pkg/rdb.(*rdbReader).readObjectValue go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/reader.go

可以看到大部分內存都是 bytes.makeSlice產生的（flat 98.94%），不過這是一個標准庫函數，再擼擼代碼，往下看可以看到redis-port實現的函數(*Loader).NextBinEntry，這里推薦使用list命令，

(pprof) list NextBinEntry
Total: 3.74GB ROUTINE ======================== github.com/CodisLabs/redis-port/pkg/rdb.(*Loader).NextBinEntry in go_workspace/src/github.com/CodisLabs/redis-port/pkg/rdb/loader.go 0 3.70GB (flat, cum) 98.94% of Total . . 137: default: . . 138: key, err := l.ReadString() . . 139: if err != nil { . . 140: return nil, err . . 141: } . 3.70GB 142: val, err := l.readObjectValue(t) . . 143: if err != nil { . . 144: return nil, err . . 145: } . . 146: entry.DB = l.db . . 147: entry.Key = key 

可以直接看到這個函數在哪一行代碼產生了多少的內存！不過如果是在可以方便導出文件的測試環境，推薦使用命令，

go tool pprof -inuse_space -cum -svg http://ip:8899/debug/pprof/heap > heap_inuse.svg

這個可以得到前后調用關系的調用棧圖，同時還包括每一層的inuse 內存大小，文件名，函數，到下一層的內存大小，分析起來簡直不能再順手。

最后定位原因就比較簡單了，redis-port在解析RDB時，是按key為粒度來處理的，遇到大key時，value可能有好幾個GB，然后redis-port直接使用了標准庫bytes.Buffer來存儲解析出來的value（對於redis hash來說是field，value對），Buffer在空間不夠的時候會自己grow，策略是當前capacity 2倍的增長速度，避免頻繁內存分配，看看標准庫的代碼（go 1.9）

// grow grows the buffer to guarantee space for n more bytes. // It returns the index where bytes should be written. // If the buffer can't grow it will panic with ErrTooLarge. func (b *Buffer) grow(n int) int { ...... } else { // Not enough space anywhere, we need to allocate. buf := makeSlice(2*cap(b.buf) + n) copy(buf, b.buf[b.off:]) b.buf = buf } ...... }

Buffer在空間不夠時，申請一個當前空間2倍的byte數組，然后把老的copy到這里，這個峰值內存就是3倍的開銷，如果value大小5GB，讀到4GB空間不夠，那么創建一個8GB的新buffer，那么峰值就是12GB了，此外Buffer的初始大小是64字節，在增長到4GB的過程中也會創建很多的臨時byte數組，gc不及時也是額外的內存開銷，所以4.5GB的RDB，在有大key的情況下，峰值內存用到15GB也就可以理解了。

1. Fix

這個問題的根本原因還是按key處理一次讀的value太大，在碰到hash這種復雜數據類型時，其實我們可以分而治之，讀了一部分value后，比如16MB就生成一個子hash，避免Buffer grow產生太大的臨時對象。

此外，解析RDB時，受限於RDB的格式，只能單個go routine處理，但是回放時，是可以由多個go routine來並發處理多個子hash，寫到目標實例的。每個子hash處理完，又可以被gc及時的清理掉。同時並發度上去了，同步的速度也有所提升（主要受限於目標Redis，因為Redis是單線程處理請求）。

最后，做個簡單的對比，可以看到優化后redis-port的RSS峰值為2.6GB，和之前相比降低了80%。

參考

• GCTRACE：https://godoc.org/runtime
• Golang profiling：https://blog.golang.org/profiling-go-programs

來源：https://yq.aliyun.com/articles/573743