Golang大杀器之跟踪剖析trace

在 Go 中有许许多多的分析工具&＃xff0c;在之前我有写过一篇 《Golang 大杀器之性能剖析 PProf》 来介绍 PProf&＃xff0c;如果有小伙伴感兴趣可以去我博客看看。

但单单使用 PProf 有时候不一定足够完整&＃xff0c;因为在真实的程序中还包含许多的隐藏动作&＃xff0c;例如 Goroutine 在执行时会做哪些操作&＃xff1f;执行/阻塞了多长时间&＃xff1f;在什么时候阻止&＃xff1f;在哪里被阻止的&＃xff1f;谁又锁/解锁了它们&＃xff1f;GC 是怎么影响到 Goroutine 的执行的&＃xff1f;这些东西用 PProf 是很难分析出来的&＃xff0c;但如果你又想知道上述的答案的话&＃xff0c;你可以用本文的主角 go tool trace 来打开新世界的大门。目录如下&＃xff1a;

初步了解

import ( "os" "runtime/trace"
)
func main() { trace.Start(os.Stderr) defer trace.Stop() ch :&＃61; make(chan string) go func() { ch <- "EDDYCJY" }() <-ch
}

生成跟踪文件&＃xff1a;

$ go run main.go 2> trace.out

启动可视化界面&＃xff1a;

$ go tool trace trace.out
2019/06/22 16:14:52 Parsing trace...
2019/06/22 16:14:52 Splitting trace...
2019/06/22 16:14:52 Opening browser. Trace viewer is listening on http://127.0.0.1:57321

查看可视化界面&＃xff1a;

• View trace&＃xff1a;查看跟踪

• Goroutine analysis&＃xff1a;Goroutine 分析

• Network blocking profile&＃xff1a;网络阻塞概况

• Synchronization blocking profile&＃xff1a;同步阻塞概况

• Syscall blocking profile&＃xff1a;系统调用阻塞概况

• Scheduler latency profile&＃xff1a;调度延迟概况

• User defined tasks&＃xff1a;用户自定义任务

• User defined regions&＃xff1a;用户自定义区域

• Minimum mutator utilization&＃xff1a;最低 Mutator 利用率

Scheduler latency profile

在刚开始时&＃xff0c;我们一般先查看 “Scheduler latency profile”&＃xff0c;我们能通过 Graph 看到整体的调用开销情况&＃xff0c;如下&＃xff1a;

因为演示程序比较简单&＃xff0c;因此这里就两块&＃xff0c;一个是 trace 本身&＃xff0c;另外一个是 channel 的收发。

Goroutine analysis

第二步看 “Goroutine analysis”&＃xff0c;我们能通过这个功能看到整个运行过程中&＃xff0c;每个函数块有多少个有 Goroutine 在跑&＃xff0c;并且观察每个的 Goroutine 的运行开销都花费在哪个阶段。如下&＃xff1a;

通过上图我们可以看到共有 3 个 goroutine&＃xff0c;分别是 runtime.main、 runtime/trace.Start.func1、 main.main.func1&＃xff0c;那么它都做了些什么事呢&＃xff0c;接下来我们可以通过点击具体细项去观察。如下&＃xff1a;

同时也可以看到当前 Goroutine 在整个调用耗时中的占比&＃xff0c;以及 GC 清扫和 GC 暂停等待的一些开销。如果你觉得还不够&＃xff0c;可以把图表下载下来分析&＃xff0c;相当于把整个 Goroutine 运行时掰开来看了&＃xff0c;这块能够很好的帮助我们对 Goroutine 运行阶段做一个的剖析&＃xff0c;可以得知到底慢哪&＃xff0c;然后再决定下一步的排查方向。如下&＃xff1a;

View trace

在对当前程序的 Goroutine 运行分布有了初步了解后&＃xff0c;我们再通过 “查看跟踪” 看看之间的关联性&＃xff0c;如下&＃xff1a;

这个跟踪图粗略一看&＃xff0c;相信有的小伙伴会比较懵逼&＃xff0c;我们可以依据注解一块块查看&＃xff0c;如下&＃xff1a;

1. 时间线&＃xff1a;显示执行的时间单元&＃xff0c;根据时间维度的不同可以调整区间&＃xff0c;具体可执行 shift &＃43; ? 查看帮助手册。

2. 堆&＃xff1a;显示执行期间的内存分配和释放情况。

3. 协程&＃xff1a;显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行&＃xff0c;其包含 GC 等待&＃xff08;GCWaiting&＃xff09;、可运行&＃xff08;Runnable&＃xff09;、运行中&＃xff08;Running&＃xff09;这三种状态。

4. OS 线程&＃xff1a;显示在执行期间有多少个线程在运行&＃xff0c;其包含正在调用 Syscall&＃xff08;InSyscall&＃xff09;、运行中&＃xff08;Running&＃xff09;这两种状态。

5. 虚拟处理器&＃xff1a;每个虚拟处理器显示一行&＃xff0c;虚拟处理器的数量一般默认为系统内核数。

6. 协程和事件&＃xff1a;显示在每个虚拟处理器上有什么 Goroutine 正在运行&＃xff0c;而连线行为代表事件关联。

点击具体的 Goroutine 行为后可以看到其相关联的详细信息&＃xff0c;这块很简单&＃xff0c;大家实际操作一下就懂了。文字解释如下&＃xff1a;

• Start&＃xff1a;开始时间

• Wall Duration&＃xff1a;持续时间

• Self Time&＃xff1a;执行时间

• Start Stack Trace&＃xff1a;开始时的堆栈信息

• End Stack Trace&＃xff1a;结束时的堆栈信息

• Incoming flow&＃xff1a;输入流

• Outgoing flow&＃xff1a;输出流

• Preceding events&＃xff1a;之前的事件

• Following events&＃xff1a;之后的事件

• All connected&＃xff1a;所有连接的事件

View Events

我们可以通过点击 View Options-Flow events、Following events 等方式&＃xff0c;查看我们应用运行中的事件流情况。如下&＃xff1a;

通过分析图上的事件流&＃xff0c;我们可得知这程序从 G1 runtime.main 开始运行&＃xff0c;在运行时创建了 2 个 Goroutine&＃xff0c;先是创建 G18 runtime/trace.Start.func1&＃xff0c;然后再是 G19 main.main.func1 。而同时我们可以通过其 Goroutine Name 去了解它的调用类型&＃xff0c;如&＃xff1a;runtime/trace.Start.func1 就是程序中在 main.main 调用了 runtime/trace.Start 方法&＃xff0c;然后该方法又利用协程创建了一个闭包 func1 去进行调用。

在这里我们结合开头的代码去看的话&＃xff0c;很明显就是 ch 的输入输出的过程了。

结合实战

今天生产环境突然出现了问题&＃xff0c;机智的你早已埋好 _"net/http/pprof" 这个神奇的工具&＃xff0c;你麻利的执行了如下命令&＃xff1a;

• curl http://127.0.0.1:6060/debug/pprof/trace\?seconds\&＃61;20 > trace.out

• go tool trace trace.out

View trace

你很快的看到了熟悉的 List 界面&＃xff0c;然后不信邪点开了 View trace 界面&＃xff0c;如下&＃xff1a;

完全看懵的你&＃xff0c;稳住&＃xff0c;对着合适的区域执行快捷键 W 不断地放大时间线&＃xff0c;如下&＃xff1a;

经过初步排查&＃xff0c;你发现上述绝大部分的 G 竟然都和 google.golang.org/grpc.(*Server).Serve.func 有关&＃xff0c;关联的一大串也是 Serve 所触发的相关动作。

这时候有经验的你心里已经有了初步结论&＃xff0c;你可以继续追踪 View trace 深入进去&＃xff0c;不过我建议先鸟瞰全貌&＃xff0c;因此我们再往下看 “Network blocking profile” 和 “Syscall blocking profile” 所提供的信息&＃xff0c;如下&＃xff1a;

Network blocking profile

Syscall blocking profile

通过对以上三项的跟踪分析&＃xff0c;加上这个泄露&＃xff0c;这个阻塞的耗时&＃xff0c;这个涉及的内部方法名&＃xff0c;很明显就是哪位又忘记关闭客户端连接了&＃xff0c;赶紧改改改。

总结

通过本文我们习得了 go tool trace 的武林秘籍&＃xff0c;它能够跟踪捕获各种执行中的事件&＃xff0c;例如 Goroutine 的创建/阻塞/解除阻塞&＃xff0c;Syscall 的进入/退出/阻止&＃xff0c;GC 事件&＃xff0c;Heap 的大小改变&＃xff0c;Processor 启动/停止等等。

希望你能够用好 Go 的两大杀器 pprof &＃43; trace 组合&＃xff0c;此乃排查好搭档&＃xff0c;谁用谁清楚&＃xff0c;即使他并不万能。

参考

• https://about.sourcegraph.com/go/an-introduction-to-go-tool-trace-rhys-hiltner

• https://www.itcodemonkey.com/article/5419.html

• https://making.pusher.com/go-tool-trace/

• https://golang.org/cmd/trace/

• https://docs.google.com/document/d/1FP5apqzBgr7ahCCgFO-yoVhk4YZrNIDNf9RybngBc14/pub

• https://godoc.org/runtime/trace