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. 分批处理,每一批数据量是常数

  • 发表于:
  • 本文为 InfoQ 中文站特供稿件
  • 首发地址https://www.infoq.cn/article/56c801b339241fd80c3b8f616
  • 如有侵权,请联系 yunjia_community@tencent.com 删除。

扫码关注云+社区

领取腾讯云代金券