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

📜📜📜今天学习的是go语言性能优化工具——pprof

性能优化原则：要定位最大瓶颈而不是细枝末节，不要过早优化，不要过度优化

工具：pprof

 

功能简介：

排查实战：

因为 cmdline 没有什么实验价值，trace 与本文主题关系不大，threadcreate 涉及的情况偏复杂，所以这三个类型的采样信息这里暂且不提。除此之外，其他所有类型的采样信息本文都会涉及到，且炸弹程序已经为每一种类型的采样信息埋藏了一个对应的性能问题，等待你的发现。

由于直接阅读采样信息缺乏直观性，我们需要借助 go tool pprof 命令来排查问题，这个命令是 go 原生自带的，所以不用额外安装。

我们先不用完整地学习如何使用这个命令，毕竟那太枯燥了，我们一边实战一边学习。

以下正式开始。

1、 排查 CPU 占用过高

我们首先通过任务管理器，查看一下炸弹程序的 CPU 占用：

可以看到 CPU 占用相当高，这显然是有问题的，我们使用 go tool pprof 来排查一下：

输入 top 命令，查看 CPU 占用较高的调用：

CPU 占用过高是 github.com/wolfogre/go-pprof-practice/animal/felidae

/tiger.(Tiger).Eat 造成的。输入 list Eat，查看问题具体在代码的哪一个位置：***

可以看到，是第 24 行那个一百亿次空循环占用了大量 CPU 时间，至此，问题定位成功！

接下来有一个扩展操作：图形化显示调用栈信息，这很酷，但是需要你事先在机器上安装 graphviz。

继续在上文的交互式终端里输入 web命令

它的实际行为是产生一个 .svg 文件，系统里设置的默认打开 .svg 的程序打开它。我的系统里打开 .svg 的默认程序是浏览器。

图中，tiger.(*Tiger).Eat 函数的框特别大，箭头特别粗，pprof 生怕你不知道这个函数的 CPU 占用很高，这张图还包含了很多有趣且有价值的信息，你可以多看一会儿再继续。

至此，这一小节使用 pprof 定位 CPU 占用的实验就结束了，你需要输入 exit 退出 pprof 的交互式终端。

为了方便进行后面的实验，我们修复一下这个问题，不用太麻烦，注释掉相关代码即可：

2、 排查内存占用过高

重新编译炸弹程序，再次运行，可以看到 CPU 占用率已经下来了，但是内存的占用率仍然很高：

我们再次运行使用 pprof 命令，注意这次使用的 URL 的结尾是 heap：

再一次使用 top、list 来定位问题代码：

list Steal（S要大写）

可以看到这次出问题的地方在 github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal

现在注释掉相关代码来解决这个问题。

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

可以看到内存占用已经将到了 20MB，似乎内存的使用已经恢复正常。

但是，内存相关的性能问题真的已经全部解决了吗？

3、排查频繁内存回收

频繁的 GC 对 golang 程序性能的影响也是非常严重的。虽然这个炸弹程序内存使用量并不高，但这会不会是频繁 GC 之后的假象呢？

为了获取程序运行过程中 GC 日志，我们需要先退出炸弹程序，再在重新启动前赋予一个环境变量，同时为了避免其他日志的干扰，使用 grep 筛选出 GC 日志查看：(这个没有实现)

GODEBUG=gctrace=1 ./go-pprof-practice | grep gc

同样使用 top、list、web 大法：

可以看到 github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run 会进行无意义的内存申请，而这个函数又会被频繁调用，这才导致程序不停地进行 GC:

**func** (d *Dog) **Run**() {

log.Println(d.Name(), "run")

_ = make([]**byte**, 16 * constant.Mi)

}

这里有个小插曲，你可尝试一下将 16 * constant.Mi 修改成一个较小的值，重新编译运行，会发现并不会引起频繁 GC，原因是在 golang 里，对象是使用堆内存还是栈内存，由编译器进行逃逸分析并决定，如果对象不会逃逸，便可在使用栈内存，但总有意外，就是对象的尺寸过大时，便不得不使用堆内存。所以这里设置申请 16 MiB 的内存就是为了避免编译器直接在栈上分配，如果那样得话就不会涉及到 GC 了。

4、排查协程泄露

由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。

我们在浏览器里可以看到，此时程序的协程数已经多达 106 条：

虽然 106 条并不算多，但对于这样一个小程序来说，似乎还是不正常的。为求安心，我们再次是用 pprof 来排查一下：

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

同样是 top、list、web 大法：

5、 排查锁的争用

到目前为止，我们已经解决这个炸弹程序的所有资源占用问题，但是事情还没有完，我们需要进一步排查那些会导致程序运行慢的性能问题，这些问题可能并不会导致资源占用，但会让程序效率低下，这同样是高性能程序所忌讳的。

我们首先想到的就是程序中是否有不合理的锁的争用，我们倒一倒，回头看看上一张图，虽然协程数已经降到 4 条，但还显示有一个 mutex 存在争用问题。

相信到这里，你已经触类旁通了，无需多言，开整。

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

同样是 top、list、web 大法：

可以看出来这问题出在 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl。但要知道，在代码中使用锁是无可非议的，并不是所有的锁都会被标记有问题，我们看看这个有问题的锁那儿触雷了。

func (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 这儿等待子协程完成任务，但由于子协程足足睡眠了一秒，导致主协程等待这个锁释放足足等了一秒钟。虽然这可能是实际的业务需要，逻辑上说得通，并不一定真的是性能瓶颈，但既然它出现在我写的“炸弹”里，就肯定不是什么“业务需要”啦。

所以，我们注释掉这段问题代码，重新编译执行，继续。

6 、排查阻塞操作

好了，我们开始排查最后一个问题。

在程序中，除了锁的争用会导致阻塞之外，很多逻辑都会导致阻塞。

可以看到，这里仍有 2 个阻塞操作，虽然不一定是有问题的，但我们保证程序性能，我们还是要老老实实排查确认一下才对。

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

top、list、web，你懂得。

可以看到，阻塞操作位于 github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee：

func (c *Cat) Pee() {

log.Println(c.Name(), "pee")

<-time.After(time.Second)

}

你应该可以看懂，不同于睡眠一秒，这里是从一个 channel 里读数据时，发生了阻塞，直到这个 channel 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。

这里有个疑点，就是上文中是可以看到有两个阻塞操作的，但这里只排查出了一个，我没有找到其准确原因，但怀疑另一个阻塞操作是程序监听端口提供 porof 查询时，涉及到 IO 操作发生了阻塞，即阻塞在对 HTTP 端口的监听上，但我没有进一步考证。

不管怎样，恭喜你完整地完成了这个实验。

】

采样过程和原理：

讲解：flat自身消耗

Cum调用函数的消耗

flat=cum当前函数没有调用其它函数，cpu的消耗是函数本身消耗的

Flat = 0函数中只有其它函数的调用

 

工作原理从过程上来说包括两个部分：性能样本数据采集和样本数据分析。

1、性能样本数据采集

在性能样本数据采集过程中，pprof 搜集被分析程序在运行时的一系列的性能概要信息的采样数据，并根据产生的采样数据生成 pprof 可视化工具可以解析的数据格式。

2、性能样本数据分析

pprof 工具本身提供了命令行工具，可以对采集到的样本数据进行可视化和性能分析。

对于 Golang 程序来说，主要关注下几方面的性能指标：

• CPU 使用情况
• 内存使用情况
• 导致阻塞（Block）的同步原语情况
• goroutine 的使用情况