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

发表于 | 分类于 ， | | 热度: ℃
字数统计: 1,844 字 | 阅读时长 ≈ 7 分钟

故障现象

某线上埋点上报机器偶尔触发内存占用过多的报警。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 tool 工具可查看如何使用 go pprof 定位内存泄漏。

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

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

go 火焰图

2. 问题复现

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

1
2
3
4
5
6
7
8
9
10
11
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 占用了.

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

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
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 上。

什么是 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😁).

本文作者：保护我方李元芳

微信订阅号

-------------本文结束感谢您的阅读-------------