devbox
很楠不爱3
这个屌丝很懒，什么也没留下！
关注作者
热门标签
热门文章
当前位置:   article > 正文

记一次Golang内存分析——基于go pprof

作者：很楠不爱3 | 2024-03-07 16:19:28

赞

踩

golang pprof heap 大小

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，

  1. 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
  2. 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
  3. 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
  4. 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
  5. 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
  6. 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
  7. 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
  8. 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
  9. 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
  10. 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
  11. 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
  12. 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
  13. 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
  14. 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
  15. 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
  16. 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
  17. 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
  18. 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
  19. 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项

  1. #->#-># MB  heap size at GC start, at GC end, and live heap
  2. # 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工具，非常强大，使用也比较方便。

我们在程序中嵌入如下几行代码，

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

在浏览器中输入http://ip:8899/debug/pprof/可以看到一个汇总页面，

  1. /debug/pprof/
  2.  
  3. profiles:
  4. 0    block
  5. 32    goroutine
  6. 552    heap
  7. 0    mutex
  8. 51    threadcreate
  9.  
  10. full goroutine stack dump

其中heap项是我们需要关注的信息，

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

包括一些汇总信息，和各个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内存值，上面的层级），

  1. (pprof) top
  2. Showing nodes accounting for 3.73GB, 99.78% of 3.74GB total
  3. Dropped 5 nodes (cum <= 0.02GB)
  4. Showing top 10 nodes out of 16
  5.       flat  flat%   sum%        cum   cum%
  6.     3.70GB 98.94% 98.94%     3.70GB 98.94%  bytes.makeSlice /usr/local/go/src/bytes/buffer.go
  7.     0.03GB  0.83% 99.78%     0.03GB  0.83%  main.(*cmdRestore).Main /usr/local/go/src/bufio/bufio.go
  8.          0     0% 99.78%     3.70GB 98.94%  bytes.(*Buffer).Write /usr/local/go/src/bytes/buffer.go
  9.          0     0% 99.78%     3.70GB 98.94%  bytes.(*Buffer).grow /usr/local/go/src/bytes/buffer.go
  10.          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
  11.          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
  12.          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
  13.          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
  14.          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
  15.          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命令，

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

可以直接看到这个函数在哪一行代码产生了多少的内存！不过如果是在可以方便导出文件的测试环境，推荐使用命令，

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

image.png

这个可以得到前后调用关系的调用栈图，同时还包括每一层的inuse 内存大小，文件名，函数，到下一层的内存大小，分析起来简直不能再顺手。

最后定位原因就比较简单了，redis-port在解析RDB时，是按key为粒度来处理的，遇到大key时，value可能有好几个GB，然后redis-port直接使用了标准库bytes.Buffer来存储解析出来的value（对于redis hash来说是field，value对），Buffer在空间不够的时候会自己grow，策略是当前capacity 2倍的增长速度，避免频繁内存分配，看看标准库的代码（go 1.9）

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

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是单线程处理请求）。

youhuaqian1.png

youhuahou1.png

最后，做个简单的对比，可以看到优化后redis-port的RSS峰值为2.6GB，和之前相比降低了80%。

参考

声明：本文内容由网友自发贡献，不代表【wpsshop博客】立场，版权归原作者所有，本站不承担相应法律责任。如您发现有侵权的内容，请联系我们。转载请注明出处：https://www.wpsshop.cn/w/很楠不爱3/article/detail/206474?site
推荐阅读
相关标签

Copyright © 2003-2013 www.wpsshop.cn 版权所有，并保留所有权利。

  

闽ICP备14008679号