pprof排查Golang服务内存问题

作者：NLP 团队刘峰

摘要

运维团队发现线上 cron 服务（cron 是我们一个微服务的名字），每天会被 k8s 重启很多次；查看线上监控发现重启前，cron 服务都达到了内存限制，初步怀疑有内存泄漏；研发团队以 cron 内存泄漏排查为例，说明如何用 pprof 来排查 Golang 服务内存相关问题。

一、pprof 介绍

是什么

Golang profiling 工具

能干什么

• CPU Profiling：分析 CPU 时间、占比，常用于定位 CPU 密集型代码的瓶颈

• Heap Profiling：分析堆内存，可以查看程序当前堆内存使用情况，或两个时刻堆内存使用差异，常用于分析程序内存相关问题

• Goroutine Profiling：Goroutine 分析，常用于排查 Goroutine 泄漏问题

• Thread、Block、Mutex 等

怎么干的

pprof 主要有两个模块 SDK 和分析工具

数据格式约定

pprof 的 SDK 和分析工具之间约定了一种数据结构profile.proto

profile.proto 格式描述了性能指标抽样数据的集合，其中每个抽样数据主要包括：

• 调用栈位置

• 当前函数，排除当前函数中调用其他函数，的指标值（例如只在当前函数中申请的堆内存）

• 当前函数，包括当前函数中调用其他函数，的指标值（例如在当前函数内部，包括调用的其他函数，申请的堆内存）

指标就是上文所说的 CPU、Heap 内存、Goroutine 数量、Thread、Block、Mutex 等

SDK

SDK 负责运行时抽样 profiling 指标，并产生 profile.proto 格式的数据，有两种集成方式：

• Runtime 方式（手写代码调用抽样，写文件）https://golang.google.cn/pkg/runtime/pprof/

• Http 方式（抽样随服务启动，提供 http api，通过 http 下载文件） https://golang.google.cn/pkg/net/http/pprof/

分析工具

分析工具负责拿到 SDK 产生的性能数据，并提供交互式的分析界面

使用 go tool pprof 命令打开分析工具，SDK 产生数据通过参数指定，数据提供方式可以是 profile.proto 格式的文件或者 http 文件流，具体使用方式可以参考pprof README

go tool pprof 提供了几种不同形式的分析界面：

• web 界面

• 交互式终端

• pprof 可视化界面

二、分析前准备

临时扩容

cron 服务线上内存限制是 8G，为了尽量保证服务可用，减少对业务的影响，排查问题前，先把内存限制改成了 20G，20G 是运维能够给我临时扩容的最大数值

代码修改

用最简单的Http方式，在 cron 服务集成了 pprof，配置文件中添加了对 pprof 端口的配置，并上线代码

运维监控

运维老王帮助写了两个脚本

获取初始化 heap

服务启动 5 分钟以后，调用 pprof 接口，dump 一个 heap 的 pprof 文件

curl http://cron:pprof_port/debug/pprof/heap -o cron-heap-base.out

复制代码

内存上涨后 heap

监控 cron 服务的内存，当内存>=5G，调用 pprof 接口， dump 一个 heap 的 pprof 文件

curl http://cron:pprof_port/debug/pprof/heap -o cron-heap.out

复制代码

选取阈值为 5G 的原因：

• 正常情况下服务内存在 1G 以下

• 被 k8s 重启时内存超过 8G

• 取一个中间值，这样大概率可以保证

￮ 已经发生了问题

￮ 不会脚本还没执行服务就已经被重启了本地环境准备

准备 Golang 环境，预先安装 graphviz

brew install graphviz

复制代码

三、分析异常情况下 heap

初步分析 pprof 文件和监控，cron 内存泄漏，平时 cron 内存在 100M、200M 左右；异常情况下，5 分钟内内存会达到 10+G、20+G，这种情况下，直接用 pprof 查看异常情况下 heap 数据应该就可以定位到哪里有问题

打开 pprof 可视化界面

go tool pprof -http=":8081" cron-heap.out

复制代码

pprof 可视化界面打开后如下图，pprof 默认展示 inuse_space 的 graph 视图

我们可以再切换到 flame graph 视图查看一下（相同的数据）

定位内存最多的代码路径

在上面 graph 视图中我们可清晰的看到一条

• 从 ScanCustomersToEsSync 函数

• 到 reflect 包的 New 函数

的调用链，其中最后的 reflect.New 函数占用了 6.42GB 的内存，当前堆中大量的新创建的对象占据了 94.26%的内存

四、分析代码

业务

上面调用栈的主要业务是进行“customer 录音数据同步”，也就是将 es 中独立的 call（录音）数据，按照 customer 分组，并写到 customer 维度的索引上，后面用 customer 维度的索引去做一些客户画像，流程大概是:

1. 拿到 1 分钟内，有新录音的 customer

2. 将这些 customers 的录音加载出来，按照 customer id 分组

3. 更新 customer 录音索引

检查代码

定时任务中的主要做事情的函数定义如下，参数是一个 bid，一个 customers，变量不会逃逸到函数外部

func (bid bson.ObjectId, customers []*models.Customer) (err error)

复制代码

这个函数 query 是 coid in，有可能发生查询出比较多 calls 的情况，有可能有问题

JSON{"coid": {"$in": coidList}}

复制代码

mongo 客户端使用正常，session 正常 close 了 

查看调用栈上所有代码后得出结论是：

• 没发现内存泄漏

• 可能是查出的 call 太多，一个 Goroutine 或者几个 Goroutine 同时调用，没有返回的时候，内存已经超过

限制，造成 cron 服务被杀死

找证据

为了验证上面的猜想，修改代码 log 中打印查出的 call 数量

上线查看 log 后，发现一次查出了 800 多万个 call，远远超出了预期

Mar 26 17:31:19 [cron] [INFO] 2020/03/26 17:31:19.701932 ... ... callCount: 8826389

复制代码

五、解决问题

代码和数据是否合理

• 确认了，拿出 customer 所有 call 的逻辑是合理的

• 正常数据应该每个 customer 只有少量的 call，有一个有问题的 bussiness，它的 customer id 是不合

理的，大量的 call 对应同一个 customer id

为什么数据有问题

• 这个 bussiness 并不需要做客户画像

• Customer id 这个字段，在这个 business 的使用场景下，并没有意义，所有每次上传 call，customer id 设置了一个固定值

解决方案

关闭这个 business 的“customer 录音数据同步”功能

六、总结

pprof 工具使用

本文简单介绍了一下 pprof，pprof 是 Golang 官方工具链的一部分，可以说是性能分析神器；pprof 对性能问题排查，日常压测中的性能瓶颈分析都非常有帮助

本文没有对 pprof 的使用做详细的说明，感兴趣的读者，可以从本文提供的链接开始了解 pprof

本文提供了 Golang 服务使用 pprof 做性能分析的几个必要的准备工作，包括代码集成、监控和脚本准备、本地环境准备

技术设计反思

本文描述了一个线上租户功能限制错误，导致写入了不合理的数据，导致服务性能问题，导致服务可用性问题，一步一步把服务搞垮的真实案例

有几点可以反思：

• 业务发展过程中，事实上已经形成的多条产品线，需要提前做功能限制

• 对于 cron 这种内存中中转的离线数据搬运业务，需要在技术设计时，考虑不合理的数据的检查和报警，避免影响服务可用性

• 对于一个后台服务，所有业务内存占用的空间复杂度，尽量保持为 O(1)；本文中 cron 服务的“customer 录音数据同步”业务，需要加载{"coid": {"$in": coidList}}个录音的数据到内存中，空间复杂度是 O(n)，这个 n 是 query 查出的 call 数量；如果想做的 O(n)可以有两种方式

a. 预估 n 一定小于某个常数（本文中显然是估计失败了）

b. 分批处理，每一批数据量是常数