Go 性能测试工具之 pprof | 青训营笔记这是我参与「第三届青训营 -后端场」笔记创作活动的第5篇笔记。 Ppro

这是我参与「第三届青训营 -后端场」笔记创作活动的第5篇笔记。

（多图预警）

性能调优工具

原则

依靠数据而不是猜测

实际的运行环境和代码逻辑执行的过程不一样
定位最大瓶颈而不是细枝末节
不要过早优化

应用在迭代过程，有些功能会很快的变化，且系统不太稳定，等到预期快出现问题再进行优化
不要过度优化

如果使用了特别的优化手段，如果进行逻辑调整，这些手段无法兼容时，会造成不稳定。

工具 pprof

pprof 是用于可视化和性能分析数据的工具。

功能简介

排查实战

搭建 pprof 项目

github.com/wolfogre/go…

go get -d github.com/wolfogre/go-pprof-practice
cd $GOPATH/src/github.com/wolfogre/go-pprof-practice
go build
./go-pprof-practice

浏览器查看指标

浏览器运行 http://localhost:6060/debug/pprof/

类型	描述	备注
allocs	内存分配情况的采样信息	可以用浏览器打开，但可读性不高
blocks	阻塞操作情况的采样信息	可以用浏览器打开，但可读性不高
cmdline	显示程序启动命令及参数	可以用浏览器打开，这里会显示 `./go-pprof-practice`
goroutine	当前所有协程的堆栈信息	可以用浏览器打开，但可读性不高
heap	堆上内存使用情况的采样信息	可以用浏览器打开，但可读性不高
mutex	锁争用情况的采样信息	可以用浏览器打开，但可读性不高
profile	CPU 占用情况的采样信息	浏览器打开会下载文件
threadcreate	系统线程创建情况的采样信息	可以用浏览器打开，但可读性不高
trace	程序运行跟踪信息	浏览器打开会下载文件，本文不涉及，可另行参阅《深入浅出 Go trace》

CPU

在终端执行 go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=10"

$> go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=10"
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=10
Saved profile in C:\Users\acker\pprof\pprof.samples.cpu.001.pb.gz
Type: cpu
Time: May 12, 2022 at 4:53pm (CST)
Duration: 10.19s, Total samples = 4.43s (43.47%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

执行 topN 命令查看占用资源最多的函数

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

(pprof) top
Showing nodes accounting for 4420ms, 99.77% of 4430ms total
Dropped 1 node (cum <= 22.15ms)
      flat  flat%   sum%        cum   cum%
    3820ms 86.23% 86.23%     3870ms 87.36%  github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat
     310ms  7.00% 93.23%      310ms  7.00%  runtime.memmove
     190ms  4.29% 97.52%      190ms  4.29%  runtime.memclrNoHeapPointers
      50ms  1.13% 98.65%      550ms 12.42%  github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal
      50ms  1.13% 99.77%       50ms  1.13%  runtime.asyncPreempt
         0     0% 99.77%     3870ms 87.36%  github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Live
         0     0% 99.77%      550ms 12.42%  github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Live
         0     0% 99.77%     4420ms 99.77%  main.main
         0     0% 99.77%      500ms 11.29%  runtime.growslice
         0     0% 99.77%     4420ms 99.77%  runtime.main

什么情况下 flat == cum?

当 flat == cum 时，函数中没有调用其他函数。

什么情况下 flat == 0？

函数中只有其他函数调用。

执行 list <regpx> 根据指定的正则表达式查找代码行

(pprof) list Eat
Total: 4.43s
ROUTINE ======================== github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat in E:\macBackup\work\go\src\github.com\wolfogre\go-pprof-practice\animal\felidae\tiger\tiger.go
     3.82s      3.87s (flat, cum) 87.36% of Total
         .          .     19:}
         .          .     20:
         .          .     21:func (t *Tiger) Eat() {
         .          .     22:   log.Println(t.Name(), "eat")
         .          .     23:   loop := 10000000000
     3.82s      3.87s     24:   for i := 0; i < loop; i++ {
         .          .     25:           // do nothing
         .          .     26:   }
         .          .     27:}
         .          .     28:
         .          .     29:func (t *Tiger) Drink() {

可以看到，第 10 行占用了 3.87s

执行 web 调用关系可视化图

执行后会自动调用浏览器打开

图中可以看出 Tiger Eat 的方法占用的最多。

注意：

如果提示 failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable file not found in %PATH%，需要安装 Graphviz

Graphviz官网：graphviz.org/

需要确保安装路径已经加入到环境变量中，最好重启终端。

参考链接
- [Graphviz绘图 - DOT语言](Graphviz绘图 - DOT语言)
- Graphviz 安装并使用 (Python) - 乌漆WhiteMoon - 博客园

Heap 堆内存

在终端执行 go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap"

参数 -http=:8080 会直接在浏览器打开可视化页面。

运行后，会直接打开浏览器显示

可以直接在 view 选对于执行命令的视图。

top 视图：

source 视图：

在这里，我们使用的是 inuse 的采样数据，可能存在一些其他内存问题没有找到。

可以点击右边的 simple 进行其他指标采样。

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

goroutine 协程

goroutine 泄露也会导致内存泄漏

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

推荐使用火焰图。

火焰图是动态的，支持点击块进行分析。由上到下表示调用顺序，每一块代表一个函数，越长代表占用 CPU 的时间越长。

可以看出，wolf.Drink 这个方法基本占用了 90% 的协程。

从 source 视图中，搜索 wolf 得到

mutex 锁

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

从 source 视图查看出问题的代码：

block 阻塞

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

如果 block 有多个却没有展示的话，可以回到 Terminal 查看命令行的视图，查看被过滤掉的。

PS C:\Users\acker> go tool pprof "http://localhost:6060/debug/pprof/block"
Fetching profile over HTTP from http://localhost:6060/debug/pprof/block
Saved profile in C:\Users\acker\pprof\pprof.contentions.delay.003.pb.gz
Type: delay
Time: May 12, 2022 at 6:35pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1494.62s, 100% of 1494.64s total
Dropped 4 nodes (cum <= 7.47s)
Showing top 10 nodes out of 15
      flat  flat%   sum%        cum   cum%
   742.86s 49.70% 49.70%    742.86s 49.70%  runtime.chanrecv1
   741.73s 49.63% 99.33%    741.73s 49.63%  sync.(*Mutex).Lock (inline)
    10.03s  0.67%   100%     10.03s  0.67%  runtime.selectgo
         0     0%   100%    741.73s 49.63%  github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl
         0     0%   100%    741.73s 49.63%  github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Live
         0     0%   100%    742.75s 49.69%  github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Live
         0     0%   100%    742.75s 49.69%  github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee
         0     0%   100%   1484.48s 99.32%  main.main
         0     0%   100%     10.14s  0.68%  net/http.(*ServeMux).ServeHTTP
         0     0%   100%     10.16s  0.68%  net/http.(*conn).serve
(pprof)

然后直接在主页中点击 block 进去查看。