记一次线上Giao(go)服务内存占用率过高问题排查

保护我方李元芳 ·

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

故障现象

某线上埋点上报机器偶尔触发内存占用过多的报警。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。触发条件主要有两个:

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

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

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