这是我参与「第三届青训营 -后端场」笔记创作活动的的第2篇笔记.
0x0 Pre
在本章会学习到以下几点
- 在go程序中搭建pprof监控后台
- 使用pprof工具监控程序CPU执行时间、堆内存状况、goroutine泄露情况、线程阻塞情况以及死锁检测
在开始之前首先需要拉取github示例代码：github.com/wolfogre/go… ，拉取代码后执行 go mod tidy 命令.
由于 pprof 可视化依赖 Graphviz 工具，因此需要提前安装 Graphviz 并且将其添加至环境变量中。
0x1 搭建pprof后台
pprof工具集成在 net/http 包下，引用时使用 _ "net/http/pprof" 只执行其包下 init() 方法将 pprof 组件注册到 http 的 handler 中。
import (
"go-pprof-practice/animal"
"log"
"net/http"
_ "net/http/pprof" // 自动注册 pprof 组件到 http handler 中
"os"
"runtime"
"time"
)
func main() {
log.SetFlags(log.Lshortfile | log.LstdFlags)
log.SetOutput(os.Stdout)
runtime.GOMAXPROCS(1)
runtime.SetMutexProfileFraction(1)
runtime.SetBlockProfileRate(1)
go func() {
if err := http.ListenAndServe(":6060", nil); err != nil {
log.Fatal(err)
}
os.Exit(0)
}()
for {
for _, v := range animal.AllAnimals {
v.Live()
}
time.Sleep(time.Second)
}
}
运行程序，进入网址 http://localhost:6060/debug/pprof ，可以看到以下界面即表示成功。
0x2 查看CPU执行时间
在 shell 中执行命令：
go tool pprof "http://localhost:6060/debug/pprof/profile?second=10"
等待10s对程序CPU执行时间采样后进入 pprof 程序执行命令行：
$ go tool pprof "http://localhost:6060/debug/pprof/profile?second=10"
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?second=10
Saved profile in /tmp/pprof/pprof.samples.cpu.005.pb.gz
Type: cpu
Time: May 12, 2022 at 5:12pm (+08)
Duration: 30.16s, Total samples = 16.08s (53.32%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
在pprof中执行 top 命令即可查看各个代码段CPU执行时间：
(pprof) top
Showing nodes accounting for 6.85s, 98.28% of 6.97s total
Dropped 49 nodes (cum <= 0.03s)
Showing top 10 nodes out of 11
flat flat% sum% cum cum%
6.21s 89.10% 89.10% 6.84s 98.13% github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat
0.63s 9.04% 98.13% 0.63s 9.04% runtime.asyncPreempt
0.01s 0.14% 98.28% 0.04s 0.57% runtime.checkTimers
0 0% 98.28% 6.84s 98.13% github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Live
0 0% 98.28% 0.04s 0.57% log.Println
0 0% 98.28% 6.88s 98.71% main.main
0 0% 98.28% 0.05s 0.72% runtime.gopreempt_m
0 0% 98.28% 0.05s 0.72% runtime.goschedImpl
0 0% 98.28% 6.88s 98.71% runtime.main
0 0% 98.28% 0.06s 0.86% runtime.mcall
其中 flat 表示当前函数执行时间，flat% 表示占CPU时间的比例，sum% 表示上面每一个之和所占执行时间比例，cum表示当前函数加上其调用函数总耗时，cum% 表示 cum 占用时间比例。
在找到占用时间的函数之后，可以使用 list [func] 命令查看函数内具体耗时的代码，可以看到上面 Eat 函数占用时间较多，因此查看 Eat函数：
(pprof) list Eat
Total: 6.97s
ROUTINE ======================== github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Eat in E:\Notes\Go\GoProject\pkg\mod\github.com\wolfogre\go-pprof-practice@v0.0.0-20190402114113-8ce266a210ee\animal\canidae\dog\dog.go
0 20ms (flat, cum) 0.29% of Total
. . 21: d.Run()
. . 22: d.Howl()
. . 23:}
. . 24:
. . 25:func (d *Dog) Eat() {
. 20ms 26: log.Println(d.Name(), "eat")
. . 27:}
. . 28:
. . 29:func (d *Dog) Drink() {
. . 30: log.Println(d.Name(), "drink")
. . 31:}
ROUTINE ======================== github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat in E:\Notes\Go\GoProject\pkg\mod\github.com\wolfogre\go-pprof-practice@v0.0.0-20190402114113-8ce266a210ee\animal\felidae\tiger\tiger.go
6.21s 6.84s (flat, cum) 98.13% of Total
. . 19:}
. . 20:
. . 21:func (t *Tiger) Eat() {
. . 22: log.Println(t.Name(), "eat")
. . 23: loop := 10000000000
6.21s 6.84s 24: for i := 0; i < loop; i++ {
. . 25: // do nothing
. . 26: }
. . 27:}
. . 28:
. . 29:func (t *Tiger) Drink() {
可以查看源码看到其中有一个长轮询，成功定位到炸弹代码，然后对炸弹进行拆除。
还可以通过 web 命令可视化结果：
(pprof) web
如果未成功运行，说明未安装Graphviz或者未添加至环境变量 结果如图：
0x3 查看堆内存
在 shell 中输出命令：
$ go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap"
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /tmp/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz
Serving web UI on http://localhost:8080
在弹出网页中可以看到占用内存的图结构：
可以看到 mouse.Steal() 函数占用了 3GB 的内存，dog.Run() 占用了 1GB。
在网页中点击 source 查看对应的源代码：
可以定位到对应的代码，然后进行“炸弹”拆除即可。
0x4 gorountine 泄露检查
由于Goroutine 实在是使用门槛实在是太低了，随手就一个就能起，出现了不少滥用的情况，有时候goroutine不能正常的关闭，就会导致 goroutine 一直驻留在内存中，导致内存占用较大和内存泄漏等情况。pprof 也可以检查goroutine 泄漏。
执行命令：
go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/goroutine"
在网页中找到 Flame Graph，可以查看每个线程执行占用时间。
可以看到 wolf.Drink() 占用了大量的时间，然后转到 source 视图下搜索 wolf 或者 Drink:
可以看到有长等待的线程未关闭，定位完毕。
0x5 其他
查看锁的状况：
go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/mutex"
查看线程阻塞的状况：
go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/block"
