Go性能分析工具pprof基本使用 | 青训营笔记

41 阅读5分钟

这是我参与「第五届青训营」伴学笔记创作活动的第 6 天

性能分析的目的是为了调优,性能调优的原则:

  • 要依靠数据而不是猜测。
  • 要定位最大瓶颈而不是细枝末节。
  • 不要过早优化。
  • 不要过度优化。

Go 自带的基准测试可以分析一个单元的性能情况,而调优的时候我们更希望知道整个应用在什么地方耗费了多少 CPU 、内存,就可以用到 pprof 。pprof 是用于可视化和分析性能分析数据的工具。

pprof 功能简介

pprof 提供了从采样到展示再到分析的完整功能:

  • 采样:
    • CPU 数据采样
    • 堆内存数据采样
    • 协程数据采样
    • 锁数据采样
    • 阻塞数据采样
    • 线程创建数据采样
  • 展示:提供多种可视化图像展示
    • Top
    • 调用图 - Graph
    • 火焰图 - FlameGraph
    • Peek
    • 源码展示 - Source
    • 反汇编 - Disassemble
  • 分析:提供两种分析方式
    • 浏览器网页
    • 可视化命令行终端
  • 在 Go 程序中引入
    • runtime/pprof
    • net/http/pprof

pprof 排查实战

项目运行

pprof实践项目:github.com/wolfogre/go…

项目提前埋下了一些炸弹代码,产生可观测的性能问题。

运行项目后,使用浏览器打开/debug/pprof的地址即可查看应用当前的各种性能数据:

CPU问题

使用pprof命令工具采集数据:

go tool pprof "http://localhost:6060/debug/pprof/profile?second=10"

采集完成后输入top

  • flat:当前函数本身的执行耗时
  • flat%flat占 CPU 总时间的百分比
  • sum%:上面每一行的flat%总和
  • cum:指当前函数本身加上其调用函数的总耗时
  • cum%cum占 CPU 总时间的比例

flat == cum时函数没有调用其他函数;flat == 0时函数中只有其他函数的调用。

从结果可见tiger.Eat这个函数占 CPU 总时间的百分比最大,因此优化目标应该在这个占比最大的函数。

接下来使用list命令查找上面发现的占比最大的函数Eat中具体哪里消耗资源最大:

即可发现是在 24 行处的循环中消耗了最大的 CPU 时间。

定位以后进行优化,这里直接注释掉这一部分的代码:

重新运行后,CPU 就降下来了:

内存问题

在 CPU 问题解决后,内存问题还没有解决:

接下来就使用pprof排查内存问题。在排查 CPU 问题的时候使用的是命令行方式,pprof也支持使用图形 UI 的方式。执行命令:

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

执行后会打开一个浏览器窗口:

即可直接查看到内存占用最多的地方在mouse.Steal函数。

在 View 中可以查看各种类型的图形展示:

可以在Source视图中查看到Steal函数中哪里占用了最多的内存:

对这部分代码进行优化,这里直接注释掉:

重启应用,内存大小也降下来了:

但是注意到刚才分析的都是inuse正在使用的内存:

Sample中可以查看其他类型的内存使用情况:

  • alloc_objects:程序累计申请的对象数
  • alloc_space:程序累计申请的内存大小
  • inuse_objects:程序当前持有的对象数
  • inuse_space:程序当前占用的内存大小

查看程序累计申请的内存大小alloc_space,发现仍然存在较大内存占用的情况:

这里的Run函数一直在申请内存,只不过申请了以后并没有使用,因此很快又被释放掉了,所以在inuse_space中排查不到这部分代码,而在alloc_space中即可排查到。将这部分代码也注释,内存问题就全部解决了。

协程问题

要查看哪方面的问题只需要把命令的后缀换一下即可:

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

同样地,即可发现协程数目过多的问题,并且可以看出问题出在wolf.Drink函数中:

分析性能问题时火焰图Flame Graph也是常用的图:

火焰图的块越长表示占用越多,也可以看出是wolf.Drink函数占用协程数目最多。

Source视图中定位具体位置:

将对应代码优化掉,协程问题即可解决。

锁的问题

同样地,将命令中的地址最后改为mutex即可查看锁的问题:

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

优化对应代码,解决锁的问题。

阻塞问题

执行命令:

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

优化cat.Pee函数的代码,解决阻塞问题。

pprof 采样原理

对于 CPU 数据的采样:

  • 采样对象:函数调用和它们占用的时间
  • 采样率:100 次/秒,固定值
  • 采样时间:从手动开启到手动结束

  • Go 进程启动操作系统的定时器,操作每隔 10ms 向 Go 进程发送一次SIGPROF信号
  • Go 进程每次收到信号就会记录调用堆栈
  • Go 进程每 100ms 读取已经记录的调用堆栈并写入输出流

对于堆内存的采样:

  • 采样程序通过内存分配器在堆上分配和释放的内存,记录分配 / 释放的大小和数量。
  • 采样率:每分配 512KB 记录一次,可在运行开头修改,1 表示每次分配均记录。
  • 采样时间:从程序运行开始到采样时。

对于 Goroutine 和 线程创建 的采样:

  • Goroutine:记录用户发起且在运行中的 goroutine (即入口非 runtime 开头的) runtime.main 的调用栈信息。
  • ThreadCreate:记录程序创建的所有系统线程的信息。

对于阻塞和锁:

  • 阻塞操作:

    • 采样阻塞操作的次数和耗时。
    • 采样率:阻塞耗时超过阈值的才会被记录,1 表示每次阻塞均记录。
  • 锁竞争:

    • 采样争抢锁的次数和耗时。
    • 采样率:只记录固定比例的锁操作,1 为每次加锁均记录。