这是我参与「第三届青训营 -后端场」笔记创作活动的的第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/,可以看到如下界面
表示了采样的数据:
| 类型 | 描述 | 备注 |
|---|---|---|
| allocs | 内存分配情况的采样信息 | 可以用浏览器打开,但可读性不高 |
| blocks | 阻塞操作情况的采样信息 | 可以用浏览器打开,但可读性不高 |
| cmdline | 显示程序启动命令及参数 | 可以用浏览器打开,这里会显示 ./go-pprof-practice |
| goroutine | 当前所有协程的堆栈信息 | 可以用浏览器打开,但可读性不高 |
| heap | 堆上内存使用情况的采样信息 | 可以用浏览器打开,但可读性不高 |
| mutex | 锁争用情况的采样信息 | 可以用浏览器打开,但可读性不高 |
| profile | CPU 占用情况的采样信息 | 浏览器打开会下载文件 |
| threadcreate | 系统线程创建情况的采样信息 | 可以用浏览器打开,但可读性不高 |
| trace | 程序运行跟踪信息 | 浏览器打开会下载文件 |
排查 CPU 占用过高
使用资源管理器可以看到程序的 CPU 占用比较高
可以使用 go tool pprof 进行排查:
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10
后面的 seconds=10 表示对10秒内的数据进行分析
结果如下:
进入 pprof 工具后,使用 top 命令可以查看 CPU 的占用情况(按 CPU 占用降序排列)
-
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 查看问题具体在代码的哪一个位置:
然后,可以定位到相关的代码,将其注释掉,可以发现 CPU 的占用大大降低:
使用 web 命令查看查看调用关系的可视化(需安装 graphviz)
排查内存占用过高
使用资源管理器可以发现程序的内存占用非常高
再次运行 pprof 命令,这次 URL 的结尾是 heap
go tool pprof http://localhost:6060/debug/pprof/heap
使用 top 命令查看内存占用情况(按内存使用降序排列)
可以看到 github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal 占用了大量的内存
使用 list Steal 查看问题代码的具体位置
同样是注释掉相关代码来解决这个问题,然后重新运行该代码,发现内存占用已经降低到了11MB
排查协程泄露
由于 golang 自带内存回收,所以一般不会发生内存泄露。但凡事都有例外,在 golang 中,协程本身是可能泄露的,或者叫协程失控,进而导致内存泄露。
在浏览器里可以看到,此时程序的协程已经多达 105 个
这对于一个小程序来说似乎是不正常的
使用 pprof 进行排查
go tool pprof http://localhost:6060/debug/pprof/goroutine
同样可以使用 top, list, web 查看相应的信息
发现这个包在不停地创建没有实际作用的协程,我们可以将其注释掉,然后重新编译运行,可以发现协程降到了4个
排查锁的争用
go tool pprof http://localhost:6060/debug/pprof/mutex
同样是使用 top 和 list 进行分析
可以看到,主协程先加锁,然后由子协程解锁,然后主协程再进行加锁,由于子协程在解锁前要睡眠1s,所以主协程可能要等待子协程一秒造成了时间的浪费
我们可以注释掉这段代码重新编译执行
排查阻塞操作
除了锁的争用会导致阻塞之外,很多逻辑都会导致阻塞。
go tool pprof http://localhost:6060/debug/pprof/block
同样是使用 top 和 list
可以看到,在 Pee() 函数中,从一个 channel 里读数据时,发生了阻塞。
火焰图
使用 go tool pprof http://localhost:6060/debug/pprof/profile 名利给你可以获得一个文件
然后用 go tool pprof -http localhost:3030 filepath
filepath 是显示文件的地址,3030 是指定要访问的端口号。