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

性能调优实战

第六天的笔记提到高质量编程的原则和实践规范以及一些性能优化建议，在实际工作中，如果要针对某个应用程序进行性能调优，应该如何进行？

简介

性能调优的原则：

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

性能分析工具pprof

pprof是一种可视化、分析性能、和分析数据的工具，他可以展示出在什么地方耗费了多少CPU、Memory。

pprof功能简介

pprof的功能在下图中罗列，具体的工具包含Golang的http标准库中也对pprof做了一些封装，采样部分包含采样程序运行时的CPU、堆内存、goroutine、锁竞争、阻塞调用和和系统线程的使用数据，再通过列表、调用图、火焰图、源码等展示出性能指标：

pprof排查实战

为了熟悉pprof工具来排查性能问题，需要动手操作来熟悉，首先构造有问题的程序（这里的示例从https://github.com/wolfogre/go-pprof-practice下载），用pprof来定位性能问题点。

图中「炸弹」代码在main中主要初始化http服务和pprof接口的代码，引入nethttpprof包后，他会将pprof的入口注册到/debug/pprof这个路径下，可通过浏览器打开这个路径查看基本性能统计。接下来需要运行「炸弹」并等待他运行稳定。

浏览器查看指标

运行稳定后，浏览器输入http://localhost:6060/debug/pprof/可以看到如下页面展示了可用的程序运行采样数据，这是引入的net/http/pprof注入的： cmdline显示运行进程的命令，threadcreate较复杂不透明，trace需要额外工具分析，「炸弹」在CPU，堆内存，goroutine，锁竞争和阻塞操作上埋了炸弹，可以使用pprof工具进行分析。

看到的数据（heap）可读性很差，需借助pprof工具更清晰读取指标。

CPU

首先排查CPU问题，下图所示CPU占用了43%，明显有异常，这里用pprof采样分析。

pprof采样原理是讲一段时间内的信息汇总输出到文件中，首先需要拿到profile文件，可以直接使用暴露的接口连接下载或直接使用pprof工具连接这个接口下载。这里使用go tool pprof+采样链接来启动采样，链接是『炸弹』暴露的接口，结尾profile代表采样对象是CPU使用。在浏览器中直接点击profile会启动60秒采样，并在结束后下载文件。这里加上seconds=10的参数仅采样10秒。采样完成后会显示如图：

接着输入top指令，可以查看CPU占用最高的函数：五列从左到右分别是：

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

上图表格默认展示资源占用最高的10个函数，如果只需要展示最高的N个函数，输入topN即可。表格第一行Tiger.Eat函数本身占用5.84秒的CPU时间，占总时间的98.82%，问题就定位了。

上图中可以看到有的行flat和cum是相等的，有的flat=0s。cum-flat得到的是函数中调用的其他函数的资源，所以在函数中没有调用其他函数时，cum-flat=0 -> flat=cum。相应的，函数中只调用了其他函数没有其他逻辑，flat=0。

接下来，输入list Eat查找这个函数，来定位是哪里出了问题。List命令会根据后面给定的正则表达式查找代码，并按行展示出每一行的占用，下图展示了第24行有一个100亿次的空循环，占用了5.84秒的CPU时间，定位成功。

除了top和list命令外，还可以输入web生成调用关系图，默认浏览器打开。图中除了每个节点的资源占用以外，还会将各个节点的调用关系串联起来，可以清楚地发现方框最大的是（* Tiger）Eat函数，比top视图更加直观。

至此，CPU的「炸弹」已经定位完成，输入q退出终端。为了对比，先将「炸弹」拆除（注释掉问题代码），重新打开程序发现CPU已经降下来了，但是内存占比很高，接下来排查内存问题。

Heap-堆内存

排查CPU问题时使用的是pprof终端，这次加入-http=：8080参数可以直接开启pprof自带的Web UI。终端输入go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap",展示除了Graph图，也能在view选项选择其他展现方式，可以明显看到最大的方块是(* Mouse)Steal()函数，占用了1.2GB内存。

根据源码发现，在(* Mouse)Steal()函数会向固定Buffer中不断追加1MB内存，直到Buffer达到1GB为止，将这块代码注释，「炸弹」已经被排除两个了：

再次运行，可以发现内存占用已经降到了20几MB，采样中也未出现异常节点了。但是内存问题没有被全部排除，在web页面右上角还有unknown_inuse_space。同时，点开sample菜单，会发现堆（heap）内存实际有四种指标：alloc_objects,alloc_space,inuse_objects,inuse_space。在堆采样中，默认展示的是inuse_space视图，及当前持有的内存，但如果有的内存已经释放，inuse采样就不会展示了。接下来，切换到alloc_space指标继续分析内存问题。

可见(* Dog).Run()中还藏着一个「炸弹」，他会每次申请16MB大小的内存，并且已经累计申请超过96MB的内存了，因为这是无意义的申请，分配结束之后会马上被GC(Garbage Collection垃圾回收)，所以在inuse采样中并不会体现。注释之后至此内存部分「炸弹」已全部拆除。

Goroutine-协程

GO是一门自带GC(垃圾回收)的语言，通常内存泄漏不会轻易发生，但例外是goroutine是很容易泄露的，进而导致内存泄露。所以接下来将分析goroutine的使用情况。

此时打开http://localhost:6060/debug/pprof/，发现「炸弹」有105条goroutine正在运行，对于简单的小程序来说是不正常的。终端输入go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/goroutine",发现graph view展示的是一张非常长的调用关系图，节点过多导致可读性很低，因此使用火焰图。

火焰图将graph view的各个节点堆叠起来，从上到下表示调用顺序；每一块代表一个函数，越长代表占用CPU的时间越长；还可以点击各个小块进行分析。可以看到(* Wolf).Drink.func1这个调用创建了大约94%的goroutine，至此定位到了问题。

在Source视图下搜索Drink可以看到函数内每次会发起10条无意义的goroutine，并且等待30s才退出，导致了goroutine的泄露。实际情况下并不止30s，这会导致不断有新的goroutine启动持续占用内存，最后CPU调度压力不断增大致使进程被系统kill掉。

注释后goroutine数量恢复到了正常水平，接下来分析下锁的问题。

mutex-锁

终端输入go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/mutex",发现存在一个锁操作。在graph view中可定位到问题函数在(* Wolf).Howl.func1()，再从source view定位到具体发生锁竞争的行数，在此函数中goroutine阻塞等待了10s才解锁，定位到了异常点。

block-阻塞

程序中会导致阻塞的原因除了锁的竞争，还会有其他逻辑例如读取channel，web页面显示还有两个block阻塞。

终端输入go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/block",可以看到(* Cat).pee()函数中读取了一个time.After()生成的channel，这就导致goroutine阻塞了一秒而不是等待1秒。

至此，定位到了一个block问题，但是还有一个在哪里呢？通过pprof top视图可以看到有4个节点cum小于2.6s被drop掉了，这就是另一个阻塞操作的节点，由于总用时小于总时长的千分之5所以被省略掉了。这样有过滤的展示对于复杂程序来说有利于定位问题。

但是另一个阻塞确实存在，需要点击哪个链接来查看呢？尽管占用低的节点不会再pprof中展示，但实际上也被记录下来了，我们可以通过暴露的接口地址直接访问。打开web中block指标的页面，可以看到第二个阻塞的操作发生在了http handler中，这个阻塞操作符合预期。

总结

至此，代码中的所有「炸弹💣」已经被定位，以上使用了五种pprof采集的常用性能指标：CPU、堆内存、Goroutine、锁竞争和阻塞；使用了两种展示方式：交互式终端和web、四种视图：Top、Graph、source、Flame Graph。pprof除了http的获取方式，也可以直接在运行时调用runtime/pprof包将指标数据输出到本地文件。