pprof性能调优实战｜青训营笔记

前言

本次课程讲解大体分为两个部分：讲述高质量编码的规范和性能调优实战，这篇文章侧重于复现使用pprof工具性能调优的实践过程，而第一部分则希望大家各自总结归纳。

pprof性能调优实战

项目地址：https://github.com/wolfogre/go-pprof-practice

这个项目中作者埋藏了很多5个性能炸弹，故意降低了项目的性能，提高资源占用量，我们将使用 pprof工具定位这些问题，并完成性能调优。

克隆项目之后，使用：go mod init go mod init github.com/wolfogre/go-pprof-practice，初始化go mod，之后就可以运行程序。

pprof预览

程序运行之后，浏览器输入 http://localhost:6060/debug/pprof/，可以查看pprof监控页面。

allocs表示分配了19次内存，block表示有3次阻塞，goroutine表示有55个协程正在运行，heap为堆上内存使用，mutex表示有1个锁竞争，threadcreate表示有7个线程创建。

通过这个面板可以先大致了解程序运行情况，并定位可能出现性能问题的位置，下面将具体排查各个问题。

优化CPU占用

我们先来看一下在活动监视器中该程序CPU占用情况：45.3%恐怖！

在Terminal窗口输入：go tool pprof"http://localhost:6060/debug/pprof/profile?seconds=10"，先pprof工具先采集10秒的数据到文件中，然后再开始接受命令去展示性能分析的结果。

输入 top命令，查看占用CPU资源较多的调用。

• flat：当前函数本身的执行耗时（flat == 0 则函数中只有其他函数的调用）
• flat%：flat占CPU总时间的比例
• sum%：上面每一行的flat%的总和
• cum：指当前函数本身加上其调用函数的总耗时（flat == cum 则函数中没有调用其他函数）
• cum%：cum占CPU总时间的比例

很明显 github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat的调用占用了绝大部分CPU。

定位到Eat方法占用资源最多之后，使用 listEat命令排查看出问题的代码具体是什么内容：

这里看到for循环执行了3.8s的时间，是问题所在。

接着输入 web命令，可以实现调用关系可视化，这个命令前提是需要下载 graphviz，一个图形化显示调用链的工具（在后续的性能调优过程中 graphviz被多次使用，这里建议先完成安装～）。

定位到问题之后，注释掉Tiger的Eat方法的耗时操作。

然后查看mac活动监视器，发现CPU的占用明显降低了到了0.2%。

在终端输入 exit退出 pprof的工作模式。

优化内存占用

CPU占用问题解决了，但是程序内存占用依旧过高。

再次在终端输入 go tool pprof http://localhost:6060/debug/pprof/heap命令，这次结尾是 heap，表示查看堆内存的占用情况，然后依旧配合输入 top、 list。

可以看到，这个for循环不断给m.buffer追加1MB的内容，并设定上限1GB，暂未看到内存的释放，所以推测这就是程序占用高内存的原因。

接着输入web，依旧会弹出一个可视化页面展示内存占用情况。

和上面解决CPU占用问题一样，这里注释掉无效分配内存的代码。

重启项目再看一下活动监视器，看到内存占用过大的问题也解决了。

排查协程问题

在最上面那张pprof状态监听图上，你可能还记得协程数量有55，而此刻再刷新一下，竟然有105，所以怀疑出现了问题，下面排查一下。

终端输入 exit退出内存的监测，重新输入 go tool pprof http://localhost:6060/debug/pprof/goroutine，开始监测协程的分配情况，输入 top、找到占用最高的方法调用 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink.func1。

执行 listDrink，定位到了Drink方法中每调用一次Drink()都会创建10个协程，然后睡眠30秒结束。

再照常使用一下 web命令，可以看到可视化的协程的创建情况。

依旧是将这部分循环创建协程的无意义代码注释掉，重启程序，再次查看pprof监测面板，协程的数量降低到了6，优化完成。

排查锁争用

这是排查的第四个性能炸弹，终端输入 go tool pprof http://localhost:6060/debug/pprof/mutex，接着输入 top、list XXX、web定位到出现锁争用的代码，web图我就不放了。

这里主协程调用了 Lock获得锁，然后开启子协程在一秒后释放锁，主协程第二次调用 Lock方法的功能是如果子协程没有调用 unLock方法，则主协程依旧会阻塞在这里，等待m锁的释放，贴一段 Lock方法的源码，这里注释给出了详细解释。

关于互斥锁其实很常用，之前写作业一二都用到了，我们无法完全断定用到了锁就会被捕获为锁竞争情况，需要额外分析，这里就当作是确实发生了锁竞争，注释掉这段代码，重启项目，然后查看pprof监测面板。

排查阻塞问题

第五个性能优化的点，因为上图中block的数量是2，表示存在阻塞，那么让我们来排查一下，在终端输入命令 go tool pprof http://localhost:6060/debug/pprof/block，然后输入 top、listPee、web命令，这里web的监测图依旧没有给出。

这里阻塞的原因是第39行代码， <-time.After实现了延时一秒的功能，那么就会因为这个人为的设定，每次多阻塞一秒，这里注释掉这部分代码，重启项目，观察pprof监测面板。

这里看到 block还有1，而且刚才 top和 list也只是定位到了一个 block，那这个1是阻塞在哪里了？我们直接在 pprof面板上点击 block，可以看到这部分 block是被隐藏起来的，通过观察发现是和 http/server相关，推测是程序正常工作需要的阻塞。

火焰图展示

此刻这个项目的5个性能炸弹都被我们修复了，但是课程中提到的Flame-Graph让人十分好奇，这里体验一下。依旧是在终端输入 go tool pprof http://localhost:6060/debug/pprof/profile命令。

前面说了，pprof监测工具是将数据存入一个文件再进行性能分析，这里定位到这个文件后，exit退出终端，然后重新执行 go tool pprof-http localhost:3030/Users/yucong/pprof/pprof.samples.cpu.004.pb.gz命令，这里的localhost:3030是你自己指定的网页监测工具访问端口。

然后就能访问在线的监测工具了，也可以切换各种展示方式。关于火焰图，方块的大小代表了占用 CPU 使用的长短，纵向表示调用链，颜色好像没特别的意义，只是配色很像火焰🔥。

结束语

pprof的实战通过监测一个包含5个性能炸弹的项目，逐步修复5个性能漏洞，学习这部分的知识将为后续编写可靠的项目代码打下坚实基础～