pprof进阶使用
火焰图
安装go-torch
uber 开源工具go-torch，可以直接读取 golang profiling 数据，并生成一个火焰图的 svg 文件。
go get -v github.com/uber/go-torch火焰图 svg 文件可以通过浏览器打开，可以通过点击每个方块来 zoom in 检查它内部的内容。
火焰图的调用顺序从下到上，每个方块代表一个函数，它上面一层表示这个函数会调用哪些函数，方块的大小代表了占用 CPU 使用的长短。火焰图的配色并没有特殊的意义，默认的红、黄配色是为了更像火焰而已。
go-torch 工具的使用非常简单，没有任何参数的话，它会尝试从http://localhost:8080/debug/pprof/profile获取 profiling 数据。它有三个常用的参数可以调整：
-u –url：要访问的 URL，这里只是主机和端口部分
-s –suffix：pprof profile 的路径，默认为 /debug/pprof/profile
–seconds：要执行 profiling 的时间长度，默认为 30s
安装 FlameGraph
要生成火焰图，需要事先安装 FlameGraph工具，这个工具的安装很简单（需要perl环境支持），只要把对应的可执行文件加入到环境变量中即可。
下载安装perl：https://www.perl.org/get.html
下载FlameGraph：
git clone https://github.com/brendangregg/FlameGraph.git将
FlameGraph目录加入到操作系统的环境变量中。
压测工具wrk
https://github.com/wg/wrk 或 https://github.com/adjust/go-wrk
火焰图与压测工具结合使用
以服务型应用为例，源码见
使用wrk对version接口进行压测:
在上面压测进行的同时，打开另一个终端执行:
30秒之后终端会出现如下提示：
然后使用浏览器打开torch.svg就能看到如下火焰图了：
火焰图的y轴表示cpu调用方法的先后，x轴表示在每个采样调用时间内，方法所占的时间百分比，越宽代表占据cpu时间越多。通过火焰图就可以更清楚的找出耗时长的函数调用，然后不断的修正代码，重新采样，不断优化。
此外还可以借助火焰图分析内存性能数据：
函数优化案例
以优化基准测试的lengthOfNonRepeatingSubStr函数为例
执行
go test -bench=Substr -v -cpuprofile=cpu.prof -benchmem在性能测试的同时取得 CPU profiling 数据文件。执行
go tool pprof -http=":8081" cpu.prof，访问http://localhost:8081
通过上图可以看出，大部分时间都花在了map相关操作
知道了性能瓶颈所在之后，优化源代码，用
[]int代替map再执行测试命令：
可以看到，执行效率从
5152279 ns/op进步到了1968375 ns/op，内存消耗从655590 B/op退步到了1179663 B/op，再执行go tool pprof -http=":8081" cpu.prof，访问http://localhost:8081
可以看到，现在CPU性能消耗只剩下了
stringtoslicerune，涉及到的就是rune(s)操作，这里是需要一个utf-8的解码操作耗费了CPU计算时间，因为必须要支持中文，这个解码操作是省不了的，所以CPU的优化到此就完成了。接下来再来看内存，观察到函数每次被调用每次都会创建一个
slice，这一点可以优化，把lastOccurred变量提取到全局变量，在函数内每次都清掉它的值，这样这个slice变量就只用初始化一次了再执行测试命令：
可以看到，内存消耗进步到了
655362 B/op，内存分配次数从2次优化到了1次，至此CPU和Memory都优化完毕了。
pprof与服务型应用
访问：http://127.0.0.1:8080/debug/pprof/
启动压力测试：
go-wrk -n 50000 http://127.0.0.1:8080/version点击 web 页面的 profile 按钮，收集信息，30 s 后会自动下载 profile 文件
拿到 profile 文件后：
go tool pprof -http=":8081" profile
定位api接口阻塞案例
编写如下有问题的代码，/push接口通过queue推送数据，但没有消费者，在推送1024次之后就会陷入阻塞：
运行服务，执行如下基准测试后陷入阻塞：
打开http://127.0.0.1:6060/debug/pprof/goroutine?debug=1，看到如下结果：
注：最好休息几分钟再做这个操作，因为刚执行完基准测试，还有1000多个正常处理了请求的存活的goroutine未被回收，会对定位问题造成干扰，等几分钟之后，阻塞的goroutine就会浮出水面了。
通过第一行，可以看到程序现存9个goroutine，第二行开头数字3，表示有3个goroutine的调用栈是如下段落的展示结果，再下一个锻炼开头数字2，表示接下来这个段落的调用栈有2个goroutine在执行。
通过这一步已经可以发现问题了，block.go:25，含义是有3个goroutine都执行到了block.go的第25行，意味着这里多半是发生了阻塞。但接下来还是进一步定位问题：
再打开http://127.0.0.1:6060/debug/pprof/goroutine?debug=2，看到如下结果：
这个页面的结果展示了所有存活的goroutine的调用栈。
第一个段落goroutine 2126 [running]含义是：id为2126的这个goroutine，当前状态是running，往下是它的调用栈，从调用栈可以发现是pprof的功能，不用管，往下看第二个段落，goroutine 1 [IO wait]，id为1的这个goroutine状态为IO wait，从调用栈可以看出是http服务相关的，本段落最后一行block.go:19可以看出，是if err := http.ListenAndServe(":6060", nil); err != nil {这一行代码，这是需要阻塞在这里的，没毛病。
再接着往下看，goroutine 2130 [chan send, 14 minutes]，id为1的这个goroutine，在做chan send操作，已经执行了14 minutes，这显然是有问题的，从调用栈可以看到是在执行block.go:25，25行代码是queue <- "hello"，到此，完全定位到了问题。
通过对比两次执行pprof的差异来快速锁定问题
刚刚执行完benchmark之后执行如下命令：
每次执行如上命令都会给出profile文件的路径，第二次执行加上-base参数指定上一次的profile文件，那么给出的分析结果就是2个pprof文件的差异。 在第一次执行go tool pprof http://127.0.0.1:6060/debug/pprof/goroutine之后发起一个curl http://127.0.0.1:6060/push，再执行如下操作：
从如上结果就可以看出，有1个goroutine阻塞在了第25行。
Last updated
Was this helpful?