记一次线上Go服务内存占用率过高问题排查

5,736 阅读6分钟

本文作者: 保护我方李元芳
商业转载请联系作者获得授权,非商业转载请注明出处。

故障现象

某线上埋点上报机器偶尔触发内存占用过多的报警。ssh到机器top发现主要内存被埋点服务占用。之前重启过几次,但是过段时间仍然会发生内存占用过多的警报。下面是报警详情。

[P1][PROBLEM][ali-e-xxx-service03.bj][][ all(#3) mem.memfree.percent 4.19575<5][O3 >2019-10-28 10:20:00]

问题推断

埋点服务主要接收客户端压缩过的上报请求,并对请求数据做解压,投递到kafka,逻辑功能相对简单。初步怀疑是某些资源没有释放导致的内存泄露或Groutine泄露。

问题排查

由于代码不是由我们业务方维护的,首先向相关部门索要了代码权限。阅读了一下源码,所有资源释放都是由defer进行操作的,并没有发现很明显的资源未释放的情况。

1. 修改线上环境配置,打开trace端口

在调试分析问题之前,熟悉go的同学都知道Golang 提供了非常方便的性能诊断工具 go tool trace; go tool trace是golang中的性能大杀器, 能揭露运行中的所有的运行时事件和内存占用等。 它是Go生态系统中用于诊断性能问题时(如延迟,并行化和竞争异常)最有用的工具之一。

由于都是采用公司的基础库,基础库专门对go trace做了封装。只需要在线上机器修改config文件,将trace信息发送到配置文件中的指定端口就可以使用go tool进行分析了。

然后我在本地进行使用go tool 工具发现网络不通,排查了一下发现trace端口没有绑定到0.0.0.0上[狗头]。 随即用proxy工具将 9900 端口反向代理到9999端口,然后使用go tool对正常状态的内存占用做了一个内存火焰图。如下图 2020-01-18-18-11-23.jpg

2. 等待故障发生

等待是个很漫长的过程,可能需要几天或者运气不好的话个把月。此处省去几万字 x#@#@$@!%?@^!。。。

3. 该来的总归还是来了

过了几天后又收到了服务器警报,由于qps上升,这次比前几次来的都早一些。接到警报后立即对内存做了一个top

go tool pprof -alloc_space http://{addr}/debug/pprof/heap
Showing top 20 nodes out of 55
      flat  flat%   sum%        cum   cum%
    2.76GB 59.76% 59.76%     2.76GB 59.76%  compress/flate.NewReader
    0.45GB  9.73% 69.49%      0.45GB  9.73%  net/http.newBufioWriterSize
    0.29GB  6.33% 75.82%     3.05GB 66.09%  compress/gzip.(*Reader).Reset
    0.25GB  5.35% 81.17%     0.25GB  5.35%  net/http.newBufioReader
    0.13GB  2.85% 84.01%     0.13GB  2.85%  runtime.rawstringtmp
    0.11GB  2.31% 86.32%     0.11GB  2.31%  bytes.makeSlice
    0.10GB  2.26% 88.58%     0.10GB  2.26%  runtime.hashGrow

每一行表示一个函数的信息。前两列表示函数使用内存以及百分比;第三列是当前所有函数累加使用 Memory 的比例;第四列和第五列代表这个函数以及子函数运行所占用的Memory和比例(也被称为累加值 cumulative),应该大于等于前两列的值;最后一列就是函数的名字。如果应用程序有性能问题,上面这些信息应该能告诉我们内存都花费在哪些函数的执行上了,另外pprof的CPU时间分析也类似。

pprof 不仅能打印出最耗内存的的地方(top),还能列出函数代码以及对应的取样数据(list)、汇编代码以及对应的取样数据(disasm),而且能以各种样式进行输出,比如 svg、gv、callgrind、png、gif等等。

可以看到的是大部分内存都被这些Reader占用了.

4. 带着问题重新阅读代码

前面我们进行了占用的初步分析,找到了内存占用多的Fcuntion是flate.NewReader,Package flate 实现了 RFC 1951 中描述的 DEFLATE 压缩数据格式, gzip 包实现了对基于 DEFLATE 的文件格式的访问。所以我们带着问题我们再次定位到相关源码实现,下面是一些关键定义:

var Gzip GzipPool
func GetReader(src io.Reader) (*gzip.Reader, error) {
	return Gzip.GetReader(src)
}

func PutReader(reader *gzip.Reader) {
	Gzip.PutReader(reader)
}

// GzipPool manages a pool of gzip.Writer.
// The pool uses sync.Pool internally.
type GzipPool struct {
	readers sync.Pool
	writers sync.Pool
}

这里用到了sync.Pool 来优化GC, 为了验证内存都在pool上,我们又使用go tool 提供的web工具对查看了一下pool的内存占用,果然大部分占用都在pool上。时间久远这次没图了。。。

5. 什么是 sync.Pool ?

sync包提供了基础的golang并发编程工具。根据官方文档的描述:

Pool's purpose is to cache allocated but unused items for later reuse, relieving pressure on the garbage collector. That is, it makes it easy to build efficient, thread-safe free lists. However, it is not suitable for all free lists.

我们通常用golang来构建高并发场景下的应用,但是由于golang内建的GC机制会影响应用的性能,为了减少GC,golang提供了对象重用的机制,也就是sync.Pool对象池。 sync.Pool是可伸缩的,并发安全的。其大小仅受限于内存的大小,可以被看作是一个存放可重用对象的值的容器。 设计的目的是存放已经分配的但是暂时不用的对象,在需要用到的时候直接从pool中取。看到这里相信许多熟悉GC的同学心里已经有答案的猜测了: 或许和GC有关。

So,Golang的GC触发时机是什么?

Golang GC1.13版本的GC实现是三色标记发配合写屏障和辅助GC。触发条件主要有两个:

  1. 超过内存大小阈值
  2. 达到定时时间

阈值是由一个gcpercent的变量控制的,当新分配的内存占已在使用中的内存的比例超过gcprecent时就会触发。 比如一次回收完毕后,内存的使用量为5M,那么下次回收的时机则是内存分配达到10M的时候。也就是说,并不是内存分配越多,垃圾回收频率越高。 如果一直达不到内存大小的阈值呢?这个时候GC就会被定时时间触发,比如一直达不到10M,那就定时(默认2min触发一次)触发一次GC保证资源的回收。

所以我们当内存占用慢慢升高的时候,gc触发次数会减少并且趋近于2min,没有gc就不会对pool中对象进行回收,导致内存占用率逐渐升高。

主动触发GC进行验证

修改代码,限制rlimit,并使用一个goroutine 每30s主动调用gc,然后进行测试后上线。观测线上接口耗时并未发生明显变化,系统运行正常,内存占用报警再也没有被触发过。

问题总结

刚开始对偶尔触发的内存报警并没有过多的在意,有许多侥幸心理,但问题总归是客观存在的,及时发现问题,定时总结才能不断进步成长,尽量避免一有问题就重启,防止成为SRB(Service ReBoot Boy😁).


参考文档

[1] golang 内存分析/动态追踪
[2] golang GC