前言
如果要说在 golang 开发过程进行性能调优，pprof 一定是一个大杀器般的工具。但在网上找到的教程都偏向简略，难寻真的能应用于实战的教程。这也无可厚非，毕竟 pprof 是当程序占用资源异常时才需要启用的工具，而我相信大家的编码水平和排场问题的能力是足够高的，一般不会写出性能极度堪忧的程序，且即使发现有一些资源异常占用，也会通过排查代码快速定位，这也导致 pprof 需要上战场的机会少之又少。即使大家有心想学习使用 pprof，却也常常相忘于江湖。
既然如此，那我就送大家一个性能极度堪忧的“炸弹”程序吧！
这程序没啥正经用途缺极度占用资源，基本覆盖了常见的性能问题。本文就是希望读者能一步一步按照提示，使用 pprof 定位这个程序的的性能瓶颈所在，借此学习 pprof 工具的使用方法。
因此，本文是一场“实验课”而非“理论课”，请读者腾出时间，脚踏实地，一步一步随实验步骤进行操作，这会是一个很有趣的冒险，不会很无聊，希望你能喜欢。
实验准备
这里假设你有基本的 golang 开发功底，拥有 golang 开发环境并配置了 $GOPATH，能熟练阅读简单的代码或进行简单的修改，且知道如何编译运行 golang 程序。此外，需要你大致知道 pprof 是干什么的，有一个基本印象即可。
此外由于你需要运行一个“炸弹”程序，请务必确保你用于做实验的机器有充足的资源，你的机器至少需要：
-
2 核 CPU；
-
2G 内存。
注意，以上只是最低需求，你的机器配置能高于上述要求自然最好。实际运行“炸弹”时，你可以关闭电脑上其他不必要的程序，甚至 IDE 都不用开，我们的实验操作基本上是在命令行里进行的。
此外，务必确保你是在个人机器上运行“炸弹”的，能接受机器死机重启的后果（虽然这发生的概率很低）。请你务必不要在危险的边缘试探，比如在线上服务器运行这个程序。
可能说得你都有点害怕了，为打消你顾虑，我可以剧透一下“炸弹”的情况，让你安心：
-
程序会占用约 2G 内存；
-
程序占用 CPU 最高约 100%（总量按“核数 * 100%”来算）；
-
程序不涉及网络或文件读写；
-
程序除了吃资源之外没有其他危险操作。
且程序所占用的各类资源，均不会随着运行时间的增长而增长，换句话说，只要你把“炸弹”启动并正常运行了一分钟，就基本确认安全了，之后即使运行几天也不会有更多的资源占用，除了有点费电之外。
获取“炸弹”
main.gopackage main
import (
// 略
_ "net/http/pprof" // 会自动注册 handler 到 http server，方便通过 http 接口获取程序运行采样报告
// 略
)
func main() {
// 略
runtime.GOMAXPROCS(1) // 限制 CPU 使用数，避免过载
runtime.SetMutexProfileFraction(1) // 开启对锁调用的跟踪
runtime.SetBlockProfileRate(1) // 开启对阻塞操作的跟踪
go func() {
// 启动一个 http server，注意 pprof 相关的 handler 已经自动注册过了
if err := http.ListenAndServe(":6060", nil); err != nil {
log.Fatal(err)
}
os.Exit(0)
}()
// 略
}
除此之外的其他代码你一律不用看，那些都是我为了模拟一个“逻辑复杂”的程序而编造的，其中大多数的问题很容易通过肉眼发现，但我们需要做的是通过 pprof 来定位代码的问题，所以为了保证实验的趣味性请不要提前阅读代码，可以实验完成后再看。
接着我们需要编译一下这个程序并运行，你不用担心依赖问题，这个程序没有任何外部依赖。
go build ./go-pprof-practice
运行后注意查看一下资源是否吃紧，机器是否还能扛得住，坚持一分钟，如果确认没问题，咱们再进行下一步。
控制台里应该会不停的打印日志，都是一些“猫狗虎鼠在不停地吃喝拉撒”的屁话，没有意义，不用细看。
使用 pprof
http://localhost:6060/debug/pprof/
页面上展示了可用的程序运行采样数据，分别有：
./go-pprof-practice因为 cmdline 没有什么实验价值，trace 与本文主题关系不大，threadcreate 涉及的情况偏复杂，所以这三个类型的采样信息这里暂且不提。除此之外，其他所有类型的采样信息本文都会涉及到，且炸弹程序已经为每一种类型的采样信息埋藏了一个对应的性能问题，等待你的发现。
go tool pprof我们先不用完整地学习如何使用这个命令，毕竟那太枯燥了，我们一边实战一边学习。
以下正式开始。
排查 CPU 占用过高
我们首先通过活动监视器（或任务管理器、top 命令，取决于你的操作系统和你的喜好），查看一下炸弹程序的 CPU 占用：
go tool pprofgo tool pprof http://localhost:6060/debug/pprof/profile
等待一会儿后，进入一个交互式终端：
[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/profile Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile Saved profile in /root/pprof/pprof.go-pprof-practice.samples.cpu.001.pb.gz File: go-pprof-practice Type: cpu Time: Apr 23, 2021 at 11:57am (CST) Duration: 30.14s, Total samples = 19.66s (65.22%) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
输入 top 命令，查看 CPU 占用较高的调用：
(pprof) top Showing nodes accounting for 19.21s, 99.48% of 19.31s total Dropped 22 nodes (cum <= 0.10s) flat flat% sum% cum cum% 19.21s 99.48% 99.48% 19.26s 99.74% go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat 0 0% 99.48% 19.26s 99.74% go-pprof-practice/animal/felidae/tiger.(*Tiger).Live 0 0% 99.48% 19.30s 99.95% main.main 0 0% 99.48% 19.30s 99.95% runtime.main
go-pprof-practice/animal/felidae/tiger.(*Tiger).Eatflatflat%sum%cumcum%list Eat(pprof) list Eat
Total: 19.31s
ROUTINE ======================== go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat in /root/go-pprof-practice/animal/felidae/tiger/tiger.go
19.21s 19.26s (flat, cum) 99.74% of Total
. . 19:}
. . 20:
. . 21:func (t *Tiger) Eat() {
. . 22: log.Println(t.Name(), "eat")
. . 23: loop := 10000000000
19.21s 19.26s 24: for i := 0; i < loop; i++ {
. . 25: // do nothing
. . 26: }
. . 27:}
. . 28:
. . 29:func (t *Tiger) Drink() {
可以看到，是第 24 行那个一百亿次空循环占用了大量 CPU 时间，至此，问题定位成功！
graphvizyum install graphviz
web如果浏览器无法使用，可以输入 svg，然后会在当前目录生成svg文件，然后使用浏览器打开也可以看到
你应该可以看到：
tiger.(*Tiger).Eatexit为了方便进行后面的实验，我们修复一下这个问题，不用太麻烦，注释掉相关代码即可：
func (t *Tiger) Eat() {
log.Println(t.Name(), "eat")
//loop := 10000000000
//for i := 0; i < loop; i++ {
// // do nothing
//}
}
之后修复问题的的方法都是注释掉相关的代码，不再赘述。你可能觉得这很粗暴，但要知道，这个实验的重点是如何使用 pprof 定位问题，我们不需要花太多时间在改代码上。
排查内存占用过高
重新编译炸弹程序，再次运行，可以看到 CPU 占用率已经下来了，但是内存的占用率仍然很高：
我们再次运行使用 pprof 命令，注意这次使用的 URL 的结尾是 heap：
go tool pprof http://localhost:6060/debug/pprof/heap
再次使用top，list来定位问题代码
[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /root/pprof/pprof.go-pprof-practice.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: go-pprof-practice
Type: inuse_space
Time: Apr 23, 2021 at 12:06pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 768MB, 100% of 768MB total
flat flat% sum% cum cum%
768MB 100% 100% 768MB 100% go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal
0 0% 100% 768MB 100% go-pprof-practice/animal/muridae/mouse.(*Mouse).Live
0 0% 100% 768MB 100% main.main
0 0% 100% 768MB 100% runtime.main
(pprof) list Steal
Total: 768MB
ROUTINE ======================== go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal in /root/go-pprof-practice/animal/muridae/mouse/mouse.go
768MB 768MB (flat, cum) 100% of Total
. . 45:
. . 46:func (m *Mouse) Steal() {
. . 47: log.Println(m.Name(), "steal")
. . 48: max := constant.Gi
. . 49: for len(m.buffer) * constant.Mi < max {
768MB 768MB 50: m.buffer = append(m.buffer, [constant.Mi]byte{})
. . 51: }
. . 52:}
go-pprof-practice/animal/muridae/mouse.(*Mouse).Stealfunc (m *Mouse) Steal() {
log.Println(m.Name(), "steal")
max := constant.Gi for len(m.buffer) * constant.Mi < max {
m.buffer = append(m.buffer, [constant.Mi]byte{})
}
}
可以看到，这里有个循环会一直向 m.buffer 里追加长度为 1 MiB 的数组，直到总容量到达 1 GiB 为止，且一直不释放这些内存，这就难怪会有这么高的内存占用了。
使用 svg 来查看图形化展示，可以再次确认问题确实出在这里：
现在我们同样是注释掉相关代码来解决这个问题。
再次编译运行，查看内存占用，可以看到内存占用已经将到了 35 MB，似乎内存的使用已经恢复正常，一片祥和。
但是，内存相关的性能问题真的已经全部解决了吗？
排查频繁内存回收
你应该知道，频繁的 GC 对 golang 程序性能的影响也是非常严重的。虽然现在这个炸弹程序内存使用量并不高，但这会不会是频繁 GC 之后的假象呢？
为了获取程序运行过程中 GC 日志，我们需要先退出炸弹程序，再在重新启动前赋予一个环境变量，同时为了避免其他日志的干扰，使用 grep 筛选出 GC 日志查看：
GODEBUG=gctrace=1 ./go-pprof-practice | grep gc
日志输出如下：
[root@master-20 ~/go-pprof-practice]#GODEBUG=gctrace=1 ./go-pprof-practice | grep gc gc 1 @0.001s 4%: 0.002+0.25+0.001 ms clock, 0.002+0.12/0.056/0+0.001 ms cpu, 16->16->0 MB, 17 MB goal, 1 P gc 2 @3.008s 0%: 0.008+0.56+0.003 ms clock, 0.008+0.25/0.15/0+0.003 ms cpu, 16->16->0 MB, 17 MB goal, 1 P gc 3 @6.011s 0%: 0.003+0.29+0.001 ms clock, 0.003+0.12/0.087/0+0.001 ms cpu, 16->16->0 MB, 17 MB goal, 1 P gc 4 @9.016s 0%: 0.006+0.48+0.003 ms clock, 0.006+0.19/0.16/0+0.003 ms cpu, 16->16->0 MB, 17 MB goal, 1 P
可以看到，GC 差不多每 3 秒就发生一次，且每次 GC 都会从 16MB 清理到几乎 0MB，说明程序在不断的申请内存再释放，这是高性能 golang 程序所不允许的。
所以接下来使用 pprof 排查时，我们在乎的不是什么地方在占用大量内存，而是什么地方在不停地申请内存，这两者是有区别的。
由于内存的申请与释放频度是需要一段时间来统计的，所有我们保证炸弹程序已经运行了几分钟之后，再运行命令：
go tool pprof http://localhost:6060/debug/pprof/allocs
同样使用 top、list、svg大法：
[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/allocs
Fetching profile over HTTP from http://localhost:6060/debug/pprof/allocs
Saved profile in /root/pprof/pprof.go-pprof-practice.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
File: go-pprof-practice
Type: alloc_space
Time: Apr 23, 2021 at 12:11pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 32MB, 100% of 32MB total
flat flat% sum% cum cum%
32MB 100% 100% 32MB 100% go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline)
0 0% 100% 32MB 100% go-pprof-practice/animal/canidae/dog.(*Dog).Live
0 0% 100% 32MB 100% main.main
0 0% 100% 32MB 100% runtime.main
(pprof) list Run
Total: 32MB
ROUTINE ======================== go-pprof-practice/animal/canidae/dog.(*Dog).Run in /root/go-pprof-practice/animal/canidae/dog/dog.go
32MB 32MB (flat, cum) 100% of Total
. . 38: log.Println(d.Name(), "pee")
. . 39:}
. . 40:
. . 41:func (d *Dog) Run() {
. . 42: log.Println(d.Name(), "run")
32MB 32MB 43: _ = make([]byte, 16 * constant.Mi)
. . 44:}
. . 45:
. . 46:func (d *Dog) Howl() {
. . 47: log.Println(d.Name(), "howl")
. . 48:}
go-pprof-practice/animal/canidae/dog.(*Dog).Runfunc (d *Dog) Run() {
log.Println(d.Name(), "run")
_ = make([]byte, 16 * constant.Mi)
}
16 * constant.Mi我们同样注释掉问题代码，重新编译执行，可以看到这一次，程序的 GC 频度要低很多，以至于短时间内都看不到 GC 日志了：
排查协程泄露
由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。
虽然 106 条并不算多，但对于这样一个小程序来说，似乎还是不正常的。为求安心，我们再次是用 pprof 来排查一下：
go tool pprof http://localhost:6060/debug/pprof/goroutine
同样是 top、list、svg大法：
[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/goroutine
Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine
Saved profile in /root/pprof/pprof.go-pprof-practice.goroutine.001.pb.gz
File: go-pprof-practice
Type: goroutine
Time: Apr 23, 2021 at 12:14pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 105, 100% of 105 total
Showing top 10 nodes out of 35
flat flat% sum% cum cum%
103 98.10% 98.10% 103 98.10% runtime.gopark
1 0.95% 99.05% 1 0.95% net/http.(*connReader).backgroundRead
1 0.95% 100% 1 0.95% runtime/pprof.writeRuntimeProfile
0 0% 100% 100 95.24% go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink.func1
0 0% 100% 1 0.95% go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl
0 0% 100% 1 0.95% go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl.func1
0 0% 100% 1 0.95% go-pprof-practice/animal/canidae/wolf.(*Wolf).Live
0 0% 100% 1 0.95% internal/poll.(*FD).Accept
0 0% 100% 1 0.95% internal/poll.(*pollDesc).wait
0 0% 100% 1 0.95% internal/poll.(*pollDesc).waitRead (inline)
(pprof) list Drink
Total: 105
ROUTINE ======================== go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink.func1 in /root/go-pprof-practice/animal/canidae/wolf/wolf.go
0 100 (flat, cum) 95.24% of Total
. . 29:
. . 30:func (w *Wolf) Drink() {
. . 31: log.Println(w.Name(), "drink")
. . 32: for i := 0; i < 10; i++ {
. . 33: go func() {
. 100 34: time.Sleep(30 * time.Second)
. . 35: }()
. . 36: }
. . 37:}
. . 38:
. . 39:func (w *Wolf) Shit() {
go-pprof-practice/animal/canidae/wolf.(*Wolf).Drinkfunc (w *Wolf) Drink() {
log.Println(w.Name(), "drink")
for i := 0; i < 10; i++ {
go func() {
time.Sleep(30 * time.Second)
}()
}
}
可以看到，Drink 函数每次回释放 10 个协程出去，每个协程会睡眠 30 秒再退出，而 Drink 函数又会被反复调用，这才导致大量协程泄露，试想一下，如果释放出的协程会永久阻塞，那么泄露的协程数便会持续增加，内存的占用也会持续增加，那迟早是会被操作系统杀死的。
我们注释掉问题代码，重新编译运行可以看到，协程数已经降到 4 条了
排查锁的争用
到目前为止，我们已经解决这个炸弹程序的所有资源占用问题，但是事情还没有完，我们需要进一步排查那些会导致程序运行慢的性能问题，这些问题可能并不会导致资源占用，但会让程序效率低下，这同样是高性能程序所忌讳的。
我们首先想到的就是程序中是否有不合理的锁的争用，我们倒一倒，回头看看上一张图，虽然协程数已经降到 4 条，但还显示有一个 mutex 存在争用问题。
相信到这里，你已经触类旁通了，无需多言，开整。
go tool pprof http://localhost:6060/debug/pprof/mutex
同样是 top、list、svg大法：
[root@master-20 ~]#go tool pprof http://localhost:6060/debug/pprof/mutex
Fetching profile over HTTP from http://localhost:6060/debug/pprof/mutex
Saved profile in /root/pprof/pprof.go-pprof-practice.contentions.delay.001.pb.gz
File: go-pprof-practice
Type: delay
Time: Apr 23, 2021 at 12:18pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 2.12mins, 100% of 2.12mins total
flat flat% sum% cum cum%
2.12mins 100% 100% 2.12mins 100% sync.(*Mutex).Unlock (inline)
0 0% 100% 2.12mins 100% go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl.func1
(pprof) list wolf
Total: 2.12mins
ROUTINE ======================== go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl.func1 in /root/go-pprof-practice/animal/canidae/wolf/wolf.go
0 2.12mins (flat, cum) 100% of Total
. . 53:
. . 54: m := &sync.Mutex{}
. . 55: m.Lock()
. . 56: go func() {
. . 57: time.Sleep(time.Second)
. 2.12mins 58: m.Unlock()
. . 59: }()
. . 60: m.Lock()
. . 61:}
go-pprof-practice/animal/canidae/wolf.(*Wolf).Howlfunc (w *Wolf) Howl() {
log.Println(w.Name(), "howl")
m := &sync.Mutex{}
m.Lock() go func() {
time.Sleep(time.Second)
m.Unlock()
}()
m.Lock()
}
可以看到，这个锁由主协程 Lock，并启动子协程去 Unlock，主协程会阻塞在第二次 Lock 这儿等待子协程完成任务，但由于子协程足足睡眠了一秒，导致主协程等待这个锁释放足足等了一秒钟。虽然这可能是实际的业务需要，逻辑上说得通，并不一定真的是性能瓶颈，但既然它出现在我写的“炸弹”里，就肯定不是什么“业务需要”啦。
所以，我们注释掉这段问题代码，重新编译执行，继续。
排查阻塞操作
好了，我们开始排查最后一个问题。
在程序中，除了锁的争用会导致阻塞之外，很多逻辑都会导致阻塞。
可以看到，这里仍有 2 个阻塞操作，虽然不一定是有问题的，但我们保证程序性能，我们还是要老老实实排查确认一下才对。
go tool pprof http://localhost:6060/debug/pprof/block
top、list、svg，你懂得。
(pprof) top
Showing nodes accounting for 5.55mins, 100% of 5.55mins total
Dropped 4 nodes (cum <= 0.03mins)
flat flat% sum% cum cum%
2.79mins 50.15% 50.15% 2.79mins 50.15% sync.(*Mutex).Lock (inline)
2.77mins 49.85% 100% 2.77mins 49.85% runtime.chanrecv1
0 0% 100% 2.79mins 50.15% go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl
0 0% 100% 2.79mins 50.15% go-pprof-practice/animal/canidae/wolf.(*Wolf).Live
0 0% 100% 2.77mins 49.85% go-pprof-practice/animal/felidae/cat.(*Cat).Live
0 0% 100% 2.77mins 49.85% go-pprof-practice/animal/felidae/cat.(*Cat).Pee
0 0% 100% 5.55mins 100% main.main
0 0% 100% 5.55mins 100% runtime.main
(pprof) list Pee
Total: 5.55mins
ROUTINE ======================== go-pprof-practice/animal/felidae/cat.(*Cat).Pee in /root/go-pprof-practice/animal/felidae/cat/cat.go
0 2.77mins (flat, cum) 49.85% of Total
. . 34:}
. . 35:
. . 36:func (c *Cat) Pee() {
. . 37: log.Println(c.Name(), "pee")
. . 38:
. 2.77mins 39: <-time.After(time.Second)
. . 40:}
. . 41:
. . 42:func (c *Cat) Climb() {
. . 43: log.Println(c.Name(), "climb")
. . 44:}