日常开发中除了会出现Panic、ErrorInfo等通过日志很容易捕捉到的错误，还会出现内存泄漏、CPU激增等日志难以捕捉的问题。今天小老虎就给大家介绍下如何使用pprof去捕捉内存、CPU这些日志难以排查到的问题。
pprof的访问
pprof是Golang的性能分析工具，可以帮助我们查看程序在运行过程中CPU、内存、协程、锁的详细信息，对于定位程序中的bug非常有帮助。在Golang内存泄漏的七种场景中小老虎对内存泄漏可能出现的场景做了详细的介绍，下面以死锁造成的内存泄漏为例，来看看怎样使用pprof定位到内存泄漏的位置。
Golang已经帮助我们封装好了一个pprof服务，我们这需要在代码中开启这个服务，并访问对于的url就可以轻松获取到程序运行时的资源情况。
//启动pprof服务供外部访问
func pprofServer() {
ip := "0.0.0.0:6060"
if err := http.ListenAndServe(ip, nil); err != nil {
fmt.Printf("start pprof failed on %s\n", ip)
}
}
//协程拿到锁未释放，其他协程获取锁会阻塞，模拟内存泄漏
func mutexTest() {
mutex := sync.Mutex{}
for i := 0; i < 10; i++ {
go func() {
mutex.Lock()
fmt.Printf("%d goroutine get mutex", i)
//模拟项目中后续代码耗时
time.Sleep(100 * time.Millisecond)
}()
}
time.Sleep(10 * time.Second)
}
func main() {
go pprofServer()
mutexTest()
}在浏览器中输入地址http://127.0.0.1:6060/debug/pprof/
比较常用的有下面五种信息
goroutine：所有goroutine的详细信息，包括协程数量，协程调用栈
heap：程序堆内存信息（每1000次内存申请采样一次）
mutex：锁的调用信息
trace：程序调用栈信息
profile：程序执行的CPU信息（每1秒采样100次）
点击查看goroutine信息
image-20220306141533652
可以看到程序一共有15个协程其中有9个协程阻塞在了获取锁的位置，将url中的debug=1改为debug=2查看每个goroutine的详细信息。
debug=2查看每个goroutine的详细信息。
可以看到协程号为21和22的协程都阻塞在了锁的获取上，阻塞时间为5min。下面再通过代码很容易就定位到了goroutine泄漏的原因是获取锁失败了。
命令行交互
实际开发中，有些程序是部署在内网服务器中的，这时没有浏览器来提供可视化的界面，就需要通过命令来查看资源的使用情况。使用命令go tool pprof url可以获取指定的profile文件，该命令会发起http请求，然后获取到资源信息存储到本地，之后就可以使用命令查看运行信息，以下是5类请求的方式：
# 下载cpu profile，默认从当前开始收集30s的cpu使用情况，需要等待30s
go tool pprof http://localhost:6060/debug/pprof/profile
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60 # wait60s
# 下载heap profile
go tool pprof http://localhost:6060/debug/pprof/heap
# 下载goroutine profile
go tool pprof http://localhost:6060/debug/pprof/goroutine
# 下载block profile
go tool pprof http://localhost:6060/debug/pprof/block
# 下载mutex profile
go tool pprof http://localhost:6060/debug/pprof/mutex等待收集完成后就可以通过命令查看相应的信息，所有的交互命令都可以通过help指令查看。
go tool pprof http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
Saved profile in /pprof/pprof.samples.cpu.016.pb.gz
Type: cpu
Time: Mar 6, 2022 at 4:15pm (CST)
Duration: 30s, Total samples = 290ms ( 0.97%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) help
Commands:
callgrind Outputs a graph in callgrind format
comments Output all profile comments
disasm Output assembly listings annotated with samples
dot Outputs a graph in DOT format
eog Visualize graph through eog
evince Visualize graph through evince
gif Outputs a graph image in GIF format
gv Visualize graph through gv
kcachegrind Visualize report in KCachegrind
list Output annotated source for functions matching regexp常用的命令有三种top、list、traces
top N：可以获取程序中资源消耗最大的前N个函数，例如输入top 10可以查看CPU消耗前十的函数
(pprof) top 10
Showing nodes accounting for 270ms, 93.10% of 290ms total
Showing top 10 nodes out of 19
flat flat% sum% cum cum%
90ms 31.03% 31.03% 130ms 44.83% runtime.kevent
40ms 13.79% 44.83% 40ms 13.79% runtime.libcCall
30ms 10.34% 55.17% 30ms 10.34% runtime.kevent_trampoline
20ms 6.90% 62.07% 50ms 17.24% runtime.checkTimers
20ms 6.90% 68.97% 250ms 86.21% runtime.findrunnable
20ms 6.90% 75.86% 20ms 6.90% runtime.lock2
20ms 6.90% 82.76% 30ms 10.34% runtime.runtimer
10ms 3.45% 86.21% 10ms 3.45% runtime.(*randomEnum).next (inline)
10ms 3.45% 89.66% 10ms 3.45% runtime.runOneTimer
10ms 3.45% 93.10% 10ms 3.45% runtime.runqgettop指令会统计下面五种信息
- flat: 函数本身占用的CPU时间。
- flat%: 本函数CPU占使用中CPU总量的百分比。
- sum%: 前面每一行flat百分比的累加，比如第2行的44.3%=第1行的31.03%+当前函数的13.79%
- cum: 是累计量，例如main函数调用子函数mutexTest，那么子函数mutexTest的CPU使用量也会被记进来
- cum%: 是累计量占总量的百分比
list func：产看某个函数的资源使用信息，函数匹配使用的是正则匹配。
(pprof) list mutexTest
Total: 7.73s
ROUTINE ======================== main.mutexTest.func1 in article/go/pprof/main.go
0 3.82s (flat, cum) 49.42% of Total
. . 19: fmt.Printf("%d goroutine get mutex", i)
. . 20: //模拟实际开发中的操作耗时
. . 21: tick := time.Tick(time.Second / 100)
. . 22: var buf []byte
. . 23: for range tick {
. 3.82s 24: buf = append(buf, make([]byte, 1024*1024)...)
. . 25: }
. . 26: time.Sleep(100 * time.Millisecond)
. . 27: wg.Done()
. . 28: }()
. . 29: }显示该函数的占用0s（小数点后俩位则被舍去），累计上子函数的调用占用3.82s，占总CPU使用时间的49.42%。耗时主要积累在第24行，占用了3.82s。
在实际项目中可能会出现不同包中函数名相同的情况，尤其是接口中函数的问题定位，如果使用模糊查找自己想看的函数会很麻烦，这里提供几种特殊的正则匹配方式。（假设包括work的多个包中都有Show方法 ，以work包的特殊处理为例）
- 模糊匹配：输入函数的名称
- 精确匹配 ：artical/go/pprof/main.Test，从根路径查找到包，使用包.方法名精确表示
- 结构体指针方法：list Show -focus = work* 只展示work包中的Show方法（等号俩边要有空格）
- 忽略某些包：list Show -work* 不展示work包中的Show方法
traces：查看函数调用栈信息
可视化工具
上面介绍的俩种方法都是pprof自带的检测方法，虽让能够帮助定位到程序的问题所在，但是每次打开CPU和内存分析文件都是密密麻麻的数字和代码，还是蛮头疼的，下面介绍pprof结合graphviz带来的可视化服务，是问题定位能够更加清晰。（首先需要下载graphviz）
首先将信息倒入到文件中curl -sK -v http://localhost:6060/debug/pprof/profile > cpu.out
然后用 go tool 工具go tool pprof -http=:8080 heap.out 使用该命令导出文件起一个服务，会自动跳到 UI 界面
节点中的数字表示flat(函数使用量) of cum(函数包括子函数的使用量) cum%(cum占总使用量的百分比)，节点越大越红表示该接节点的flat值越大，线越粗表示指向的节点cum值越大。
VIEW
image-20220306173905386
Top：和top命令相同，将函数按资源使用进行排名
Graph：如图的函数调用逻辑图以及节点使用
Flame Graph：火焰图，资源使用按从大到小排列，点击可看详细信息
Peek：打印每个调用栈的信息
Source：显示具体函数的资源消耗信息，类似list命令
Disassemble：显示样本总量
SAMPLE
img
如果是内存信息SAMOLE这一栏有四个选项
alloc_objects：已分配的对象总量（不管是否已释放）
alloc_space：已分配的内存总量（不管是否已释放）
inuse_objects：已分配但尚未释放的对象数量
inuse_sapce：已分配但尚未释放的内存数量
REFINE
搭配搜索框使用按正则表达式对内容进行过滤（list命令）
总结
本文介绍了pprof自带的浏览器访问方式，以及在服务器上通过命令获取资源信息的方式和三种常用命令，top可以获取程序中子源消耗的函数排名，list可以获取指定函数的详细信息，trance可以打印出函数的调用栈。最后介绍了ppro结合graphviz带来的可视化服务，可以使得操作更加便利，火焰图更是直观简洁，能够帮助我们快速定位问题所在
标签：profile,http,pprof,debug,内存,go,groutine From： https://blog.51cto.com/u_15257216/7723267