在上文 Go 性能分析工具 PProf(上)介绍了查看 Go 进程的 CPU、内存、火焰图。
但有时候使用 pprof 还不一定足够完整观查并解决问题,因为在真实的程序中还包含许多的隐藏动作,例如 Goroutine 在执行时会做哪些操作?执行/阻塞了多长时间?在什么时候阻止?在哪里被阻止的?GC 是怎么影响到 Goroutine 的执行的?
这就需要 Go 的 trace 工具来进行分析。
trace 工具是用于分析程序运行时行为的强大工具,它能生成程序执行期间的事件时间线,帮助开发者深入理解程序的并发、调度、垃圾回收(GC)、系统调用等底层行为。
类似的,执行命令
curl -o trace.out "http://localhost:6060/debug/pprof/trace?seconds=30"
采集程序信息,并生成 trace.out 文件,再执行命令:
go tool trace trace.out
启动可视化界面:
1、Scheduler latency profile
在刚开始查看问题时,除非是很明显的现象,否则不应该一开始就陷入细节,因此我们一般先查看 “Scheduler latency profile”,我们能通过 Graph 看到整体的调用开销情况,如下:
2、Goroutine 分析
第二步看 “Goroutine analysis”,我们能通过这个功能看到整个运行过程中,每个函数块有多少个有 Goroutine 在跑,并且观察每个的 Goroutine 的运行开销都花费在哪个阶段。
这里可以明显看到 gc 耗费了大量时间,问题应该出在 gc 上。
3、View trace by proc
现在看 View trace by proc,跟进进程查看 trace。
一个正常的 trace 图如下,横轴为时间线,纵轴为各项指标。
一个不正常的 trace 图如下
可以看到,大概 10s 发生 7次 GC,并且 GC 后,Heap 几乎没有下降,可以定位到应该是 GC 出现问题,
4、Minimum mutator utilization
在 Go 的 trace 工具中,MMU(Minimum Mutator Utilization) 是一个衡量垃圾回收(GC)对程序性能影响的重要指标,表示在特定时间窗口内,应用程序(Mutator)能够执行的最小 CPU 利用率比例。MMU 越低,说明 GC 对程序运行的干扰越大。
横坐标表示时间窗口,纵坐标 mmu 是指除了 GC 外程序占用 CPU 的最小的比例。
较为正常的 MMU 曲线应该是这样:
MMU的线性状态理想目标
- MMU值应尽可能高(接近100%),表示GC对应用的影响极小,程序几乎无感知停顿。
- 曲线应保持平稳,避免频繁的剧烈波动,否则表明GC活动不稳定或存在突发性内存压力。
而不正常的 MMU 差不多是这样:
可以看到几乎全部时间都在 gc。
5、总结
通过本文我们习得了 go tool trace 的武林秘籍,它能够跟踪捕获各种执行中的事件,例如 Goroutine 的创建/阻塞/解除阻塞,Syscall 的进入/退出/阻止,GC 事件,Heap 的大小改变,Processor 启动/停止等等。
需要用好 Go 的两大杀器 pprof + trace 组合,此乃排查好搭档,谁用谁清楚,即使他并不万能。
最后,上面这些都需要服务器正处于异常状态,才能采集到异常信息,如果服务器半夜三更处于异常,而到白天又恢复正常了,怎么知道异常原因呢?Go 性能监控—holmes 可以很好的解决问题。