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

217 阅读4分钟

这是我参与「第三届青训营 -后端场」笔记创作活动的的第1篇笔记

获取程序的代码 git clone https://github.com/wolfogre/go-pprof-practice.git

克隆项目后,使用 go mod init github.com/wolfogre/go-pprof-practice 对项目进行初始化

使用

go build
./go-pprof-practice

运行程序。程序运行后,控制台里会不停地打印日志。

使用pprof

运行程序,打开浏览器访问 http://localhost:6060/debug/pprof/,可以看到如下界面

image.png

表示了采样的数据:

类型描述备注
allocs内存分配情况的采样信息可以用浏览器打开,但可读性不高
blocks阻塞操作情况的采样信息可以用浏览器打开,但可读性不高
cmdline显示程序启动命令及参数可以用浏览器打开,这里会显示 ./go-pprof-practice
goroutine当前所有协程的堆栈信息可以用浏览器打开,但可读性不高
heap堆上内存使用情况的采样信息可以用浏览器打开,但可读性不高
mutex锁争用情况的采样信息可以用浏览器打开,但可读性不高
profileCPU 占用情况的采样信息浏览器打开会下载文件
threadcreate系统线程创建情况的采样信息可以用浏览器打开,但可读性不高
trace程序运行跟踪信息浏览器打开会下载文件

排查 CPU 占用过高

使用资源管理器可以看到程序的 CPU 占用比较高

image.png

可以使用 go tool pprof 进行排查:

go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10

后面的 seconds=10 表示对10秒内的数据进行分析

结果如下:

image.png

进入 pprof 工具后,使用 top 命令可以查看 CPU 的占用情况(按 CPU 占用降序排列)

image.png

  • flat:当前函数本身的执行耗时(flat == 0 则函数中只有其他函数的调用)

  • flat%:flat占CPU总时间的比例

  • sum%:上面每一行的flat%的总和

  • cum:指当前函数本身加上其调用函数的总耗时(flat == cum 则函数中没有调用其他函数)

  • cum%:cum占CPU总时间的比例

可以看到 CPU 占用过高是 github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat 造成的

通过 list Eat 查看问题具体在代码的哪一个位置:

image.png

然后,可以定位到相关的代码,将其注释掉,可以发现 CPU 的占用大大降低:

image.png

使用 web 命令查看查看调用关系的可视化(需安装 graphviz)

image.png

排查内存占用过高

使用资源管理器可以发现程序的内存占用非常高

image.png

再次运行 pprof 命令,这次 URL 的结尾是 heap

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

使用 top 命令查看内存占用情况(按内存使用降序排列)

image.png

可以看到 github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal 占用了大量的内存

使用 list Steal 查看问题代码的具体位置

image.png

同样是注释掉相关代码来解决这个问题,然后重新运行该代码,发现内存占用已经降低到了11MB

image.png

排查协程泄露

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

在浏览器里可以看到,此时程序的协程已经多达 105 个

image.png

这对于一个小程序来说似乎是不正常的

使用 pprof 进行排查

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

同样可以使用 top, list, web 查看相应的信息

image.png

image.png

发现这个包在不停地创建没有实际作用的协程,我们可以将其注释掉,然后重新编译运行,可以发现协程降到了4个

image.png

排查锁的争用

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

同样是使用 top 和 list 进行分析

image.png

可以看到,主协程先加锁,然后由子协程解锁,然后主协程再进行加锁,由于子协程在解锁前要睡眠1s,所以主协程可能要等待子协程一秒造成了时间的浪费

我们可以注释掉这段代码重新编译执行

排查阻塞操作

除了锁的争用会导致阻塞之外,很多逻辑都会导致阻塞。

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

同样是使用 top 和 list

image.png

可以看到,在 Pee() 函数中,从一个 channel 里读数据时,发生了阻塞。

火焰图

使用 go tool pprof http://localhost:6060/debug/pprof/profile 名利给你可以获得一个文件

然后用 go tool pprof -http localhost:3030 filepath

filepath 是显示文件的地址,3030 是指定要访问的端口号。

image.png

小结

image.png