記一次Golang記憶體分析——基於gopprof

夏周tony發表於2018-03-31

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也就可以理解了。

這個問題的根本原因還是按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

關於redis記憶體分析，記憶體優化
2020-05-16
Redis記憶體優化
記一次堆外記憶體洩漏分析
2024-06-03
記憶體
Golang 共享記憶體
2020-02-24
Golang記憶體
記一次 .NET 某工控軟體記憶體洩露分析
2022-12-06
記憶體洩露
記一次記憶體告警
2018-12-18
記憶體
Linux下基於記憶體分析的Rootkit檢測方法
2020-08-19
Linux記憶體
golang手動管理記憶體
2018-04-27
Golang記憶體
記一次 .NET 某電力系統記憶體暴漲分析
2023-09-18
記憶體
記一次 .NET 某外貿ERP 記憶體暴漲分析
2023-04-23
記憶體
golang 垃圾回收器如何標記記憶體？
2021-06-29
Golang記憶體
一次glide記憶體洩漏排查分析
2024-05-10
IDE記憶體
Ubuntu記憶體分析
2019-01-22
Ubuntu記憶體
JVM記憶體分析
2018-05-27
JVM記憶體
記一次 .NET 某餐飲小程式記憶體暴漲分析
2023-09-21
記憶體
記一次 .NET 醫院CIS系統記憶體溢位分析
2021-05-08
記憶體溢位
記一次 .NET 某外貿Web站記憶體洩漏分析
2021-09-09
Web記憶體
【Java基礎】實體記憶體&虛擬記憶體
2024-10-19
Java記憶體
golang 切片記憶體應用技巧
2019-12-12
Golang記憶體
記一次 WinDbg 分析 .NET 某工廠MES系統記憶體洩漏分析
2022-01-10
記憶體
記一次記憶體飆升的Windbg
2020-09-04
記憶體
記一次老商家端應用記憶體突然飈高原因分析
2023-10-31
記憶體
記一次 Windows10 記憶體壓縮模組崩潰分析
2023-04-26
Windows記憶體
記一次 .NET某裝潢ERP系統記憶體暴漲分析
2023-02-27
記憶體
記一次 .NET 某電廠Web系統記憶體洩漏分析
2022-07-14
Web記憶體
記一次 .NET 某風控管理系統記憶體洩漏分析
2021-11-02
記憶體
記一次 .NET 某婦產醫院 WPF記憶體溢位分析
2021-12-10
記憶體溢位
記一次 .NET醫療布草API程式記憶體暴漲分析
2021-04-29
API記憶體
記一次網頁記憶體溢位分析及解決實踐
2019-01-15
網頁記憶體溢位
11-記憶體分析
2024-06-23
記憶體
Go記憶體逃逸分析
2022-02-28
Go記憶體
20201209——java記憶體分析
2020-12-10
Java記憶體
Java 物件記憶體分析
2020-12-03
Java物件記憶體
nginx共享記憶體分析
2019-02-11
Nginx記憶體
記憶體效能分析工具
2019-02-20
記憶體
基於RT1052 Aworks 記憶體擴容記錄（一）
2021-08-21
記憶體
pprof 分析mysqld 記憶體呼叫（筆記）
2021-12-14
MySql記憶體筆記
記錄node記憶體瓶頸分析
2018-03-23
記憶體
Linux記憶體洩露案例分析和記憶體管理分享
2024-10-24
Linux記憶體洩露

記一次Golang記憶體分析——基於gopprof

1. 背景

2. 分析

2.1 GCTRACE

2.2 Golang pprof

參考

相關文章