pprof 实战 | 青训营

86 阅读6分钟

一.实验准备

1.Graphviz图形化依赖安装

pprof默认使用命令行的方式来查看各项数据,但这明显不够直观,所以我安装了一个图形化工具Graphviz

Download | Graphviz

graphviz下载.png

安装完毕

2.获取拥有性能问题的代码

首先通过git从github上克隆需要进行pprof测试的源码

clone.png

克隆完后先编译一下程序并运行

运行.png

程序一直在不断打印

二.使用pprof排查cpu问题

现在保持程序运行,打开浏览器访问 http://localhost:6060/debug/pprof/,可以看到如下页面:

1.png

然后我打开任务管理器查看cpu占用,此时可以看到 CPU 占用

image.png

我发现程序的cpu占用较高,此时使用 go tool pprof 来采集 10 秒 CPU 数据排查下问题:

  go tool pprof http://localhost:6060/debug/pprof/profile

等待10s后进入一个终端:

1.png

输入top命令,查看cpu占用较高的调用:

top.png

参数说明:

类型描述
flat当前函数本身的执行耗时
flat%flat 占 CPU 总时间的比例
sum%上面每一行的 flat% 总和
cum当前函数本身加上其周期函数的总耗时
cum%cum 占 CPU 总时间的比例

从中可以看出Eat方法导致了cpu占用过高,输入list eat查看问题具体在代码的哪个位置

eat.png

从输出结果里可以看到对应的文件为 animal/felidae/tiger/tiger.go,在代码的第24行我发现一个100亿次的for循环,这就是造成cpu占用过高的原因

接下来通过graphviz图形依赖,在git终端使用web命令来生成可视化页面

image.png

上图中Eat函数所在框很大,指向它的箭头也更粗,说明这个函数cpu占用很高,接下来我找到Eat函数注释掉相关代码:

image.png

修改后cpu占用降低

image.png

三.排查堆内存问题

虽然cpu占用的问题解决了,但是我发现内存的使用也非常高,接下来继续排查内存问题

在git终端输入 go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap"

image.png

从上图中我发现mouse的Steal方法占用内存最多,然后点击网页左上角的view->source,可以查看到具体的代码文件及行数:

image.png

从代码中可以看到这么高的内存占用是因为程序会一直向 m.buffer 里追加长度为 1 MiB 的数组,直到总容量到达 1 GiB 为止,因此我直接注释掉Steal方法的相关代码来解决这个问题。

image.png

再次编译运行,查看内存占用:

image.png

此时内存恢复正常,但是运行一段时间后仍然会升高,这是因为后面有模拟内存泄露的炸弹

四.排查协程问题

根据debug页面,我发现此时程序有113条协程,对于该程序来说并不正常:

image.png

使用go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/goroutine"查看堆内存占用情况 
然后点击view->Flame Graph

得到如下的火焰图

image.png

从火焰图中可以看到wolf.(*Wolf).Drink.func1 这个函数占了总 goroutine 数量的80%

接下来切换 source 页面,查看代码具体位置:

image.png

可以看到Drink每次会发起 10 个协程,每个协程会 sleep 30 秒再执行,而 Drink 函数又被反复的调用,导致了大量的协程泄漏。

注释掉相关代码:

image.png

重新运行后再次查看debug页面,发现协程数量已经大幅度降低:

image.png

五.排查锁(mutex)

通过对debug页面的观察可以发现一个mutex 争用问题

首先打开可视化页面

go tool pprof -http=:8080 http://localhost:6060/debug/pprof/mutex

image.png

通过source发现问题代码:

image.png

可以看到,这个锁由主协程 Lock,并启动子协程去 Unlock,主协程会阻塞在第二次 Lock 这里等待子协程完成任务,但由于子协程睡眠了一秒,导致主协程等待这个锁释放等了一秒钟。对此处代码进行修改即可解决问题。

image.png

可以看到mutex变为0

image.png

六.排查阻塞(Block)

观察debug页面,发现有2个阻塞的操作:

image.png

打开可视化界面:

go tool pprof -http=:8080 http://localhost:6060/debug/pprof/block

image.png

再通过source查看问题代码:

image.png

可以看到这里是从一个 channel 里读数据时,发生了阻塞。直到这个 channel 在一秒后才有数据读出,因此这里会导致程序阻塞,而不是睡眠。

把代码注释掉:

image.png

重新编译运行后发现程序还有一个 block。通过排查分析后发现是因为程序提供了 HTTP 的 pprof 服务,程序阻塞在对 HTTP 端口的监听上,因此这个阻塞是正常的。

七.基准比对的排查方式

pprof 中有一个 -base 选项,它用于指定基准采样文件,这样可以通过比较两个采样数据,从而查看到指标的变化,例如函数的 CPU 使用时间或内存分配情况。

运行这个炸弹程序,将启动时的堆内存分配情况保存下来,在终端中执行 curl -o heap-base http://localhost:6060/debug/pprof/heap 来下载。

当程序的运行时间越来越长,所占用的内存也越来越大,此时再执行 curl -o heap-target http://localhost:6060/debug/pprof/heap 获取到当前的采样数据。

再获取到两个样本数据后,我们通过 base 选项将 heap-base 作为基准,查看运行的这段时间内哪里内存增长了

go tool pprof -http=:8080 -base heap-base heap-target

image.png

从图中可以发现在这段时间中 mouse 的 Pee 方法增长了 1.31GB,这就是内存泄漏的地方

然后点击view->source查看问题代码:

image.png

将其注释掉:

image.png

至此,我通过pprof工具成功解决了该程序的性能问题

总结

pprof是一个非常强大的性能分析工具,它不仅能检测出程序中的各类性能问题,而且还能配合graphviz图形依赖指出造成性能问题的代码及其位置,方便程序员快速准确的对代码进行优化,解决整个程序的性能问题。

我在pprof的实战过程中收获颇多,不仅熟悉了pprof工具和graphviz图形依赖的使用,还巩固了性能调优的相关知识。不过遗憾的是该项目的优化方式只是简单粗暴的注释掉问题代码,没有机会让我实践如何在不影响代码功能的情况下优化程序性能。

总的来说,这次实战过程让我体会到了一个项目的优劣不单单在于它功能的实现方式有多么的巧妙,还要考虑整个程序的性能是否能够达标