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

故障现象

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

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

问题推断

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

问题排查

因为代码不是由咱们业务方维护的，首先向相关部门索要了代码权限。阅读了一下源码，全部资源释放都是由defer进行操做的，并无发现很明显的资源未释放的状况。web

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

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

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

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

2. 等待故障发生

等待是个很漫长的过程，可能须要几天或者运气很差的话个把月。此处省去几万字 x#@#@$@^!。。。bash

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😁).

参考文档