例子 gist 来自之前的 Trie 的实现, Ruby vs Go.

main 函数加上了下面几行:

1
2
3
4
5 6 
import "runtime/pprof"
// ...
cpuProfile, _ := os.Create("cpu_profile") pprof.StartCPUProfile(cpuProfile) defer pprof.StopCPUProfile() // ...

这里 os.Create("cpu_profile") 指定生成的数据文件, 然后 pprof.StartCPUProfile 看名字就知道是开始对 CPU 的使用进行监控. 有开始就有结束, 一般直接跟着 defer pprof.StopCPUProfile() 省的后面忘了. 编译执行一次以后会在目录下生成监控数据并记录到 cpu_profile. 接着就可以使用 pprof 来解读分析这些监控生成的数据.

When CPU profiling is enabled, the Go program stops about 100 times per second and records a sample consisting of the program counters on the currently executing goroutine’s stack.

CPU Profiling

1
2
3
4
5 6 
$ go tool pprof cpu_profile Type: cpu Time: Jan 22, 2019 at 3:02pm (CST) Duration: 518.52ms, Total samples = 570ms (109.93%) Entering interactive mode (type "help" for commands, "o" for options) (pprof)

因为是在多核环境, 所以, 取样时间(Total samples) 占比大于 100% 也属于正常的. 交互操作模式提供了一大票的命令, 执行一下 help 就有相应的文档了. 比如输出报告到各种格式(pdf, png, gif), 方块越大个表示消耗越大.

又或者列出 CPU 占比最高的一些(默认十个)运行结点的 top 命令, 也可以加上需要的结点数比如 top15

 1
 2
 3
 4
 5  6  7  8  9 10 11 12 13 14 
(pprof) top
Showing nodes accounting for 480ms, 84.21% of 570ms total Showing top 10 nodes out of 67 flat flat% sum% cum cum% 200ms 35.09% 35.09% 210ms 36.84% main.NewNode (inline) 70ms 12.28% 47.37% 170ms 29.82% runtime.scanobject 60ms 10.53% 57.89% 70ms 12.28% runtime.greyobject 30ms 5.26% 63.16% 30ms 5.26% runtime.memclrNoHeapPointers 30ms 5.26% 68.42% 30ms 5.26% runtime.memmove 20ms 3.51% 71.93% 250ms 43.86% main.(*Node).insert 20ms 3.51% 75.44% 20ms 3.51% runtime.findObject 20ms 3.51% 78.95% 230ms 40.35% runtime.gcDrain 20ms 3.51% 82.46% 20ms 3.51% runtime.pthread_cond_wait 10ms 1.75% 84.21% 10ms 1.75% runtime.(*gcWork).tryGetFast (inline)
  • flat: 是指该函数执行耗时, 程序总耗时 570ms, main.NewNode 的 200ms 占了 35.09%
  • sum: 当前函数与排在它上面的其他函数的 flat 占比总和, 比如 35.09% + 12.28% = 47.37%
  • cum: 是指该函数加上在该函数调用之前累计的总耗时, 这个看图片格式的话会更清晰一些.

可以看到, 这里最耗 CPU 时间的是 main.NewNode 这个操作.

除此外还有 list 命令可以根据匹配的参数列出指定的函数相关数据, 比如:

Memory Profiling

1
2
3

// ...
memProfile, _ := os.Create("mem_profile") pprof.WriteHeapProfile(memProfile)

类似 CPU 的监控, 要监控内存的分配回收使用情况, 只要调用 pprof.WriteHeapProfile(memProfile)

然后是跟上面一样的生成图片:

Type: inuse_space 是监控内存的默认选项, 还可以选 -alloc_space, -inuse_objects, -alloc_objects

inuse_space 是正在使用的内存大小, alloc_space是从头到尾一共分配了的内存大小(包括已经回收了的), 后缀为 _objects 的是相应的对象数

net/http/pprof

对于 http 服务的监控有一些些的不同, 不过 Go 已经对 pprof 做了一些封装在 net/http/pprof

例子 gist 来自从 net/http 入门到 Gin 源码梳理

引入多一行 _ "net/http/pprof", 启用服务以后就可以在路径 /debug/pprof/ 看到相应的监控数据. 类似下面(已经很贴心的把各自的描述信息写在下边了):

用 wrk (brew install wrk) 模拟测试

wrk -c 200 -t 4 -d 3m http://localhost:8080/hello

还是没有前面的那些可视化图形 UI 直观, 不过可以通过 http://localhost:8080/debug/pprof/profile (其他几个指标也差不多, heap, alloc…)生成一个类似前面的 CPU profile 文件监控 30s 内的数据. 然后就可以用 go tool pprof来解读了.

 1
 2
 3
 4
 5  6  7  8  9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 
Type: cpu
Time: Jan 22, 2019 at 4:22pm (CST) Duration: 30.13s, Total samples = 1.62mins (321.66%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 93.78s, 96.76% of 96.92s total Dropped 270 nodes (cum <= 0.48s) Showing top 10 nodes out of 52 flat flat% sum% cum cum% 81.42s 84.01% 84.01% 81.45s 84.04% syscall.Syscall 3.45s 3.56% 87.57% 3.45s 3.56% runtime.kevent 2.31s 2.38% 89.95% 2.31s 2.38% runtime.pthread_cond_wait 2.06s 2.13% 92.08% 2.07s 2.14% runtime.usleep 1.93s 1.99% 94.07% 1.93s 1.99% runtime.pthread_cond_signal 1.10s 1.13% 95.20% 1.10s 1.13% runtime.freedefer 0.85s 0.88% 96.08% 0.87s 0.9% runtime.nanotime 0.59s 0.61% 96.69% 4.07s 4.20% runtime.netpoll 0.04s 0.041% 96.73% 0.67s 0.69% runtime.newproc1 0.03s 0.031% 96.76% 44.18s 45.58% net/http.(*conn).readRequest (pprof) Type: alloc_space Time: Jan 22, 2019 at 4:26pm