Go语言中文网，每天致力于分享编码、开源等知识，欢迎关注我，会有意想不到的收获！

Go里有很多分析工具。之前写过一篇Golang killer PProf的性能分析来介绍PProf。如果你有兴趣，你可以访问我的博客。

但是单独使用PProf有时候不够完整，因为真实的程序中有很多隐藏的动作，比如Goroutine在执行的时候会做什么？执行/阻止了多长时间？什么时候会停止？在哪里停的？谁又把它们锁上/打开了？GC如何影响Goroutine的执行？这些东西很难用PProf来分析，但是如果你想知道上面的答案，可以用这篇文章的主角gotooltrace来打开一扇新世界的大门。该目录如下：

初步了解

生成跟踪文件：

$gorunmain.go2trace.out启动可视化界面：

gotooltracetrace . out 2019/06/2216333635.2019/06/2216:14:52拆分跟踪.2019/06/2216:14336052打开浏览器。traceviewerissling on http://127 . 0 . 0 . 136057321查看可视化界面：

View Trace:View Trace Goroutineanalysis:Goroutine Analysis Networkblockingprofile:Networkblockingprofile:Synchronizationblockingprofile:Synchronizationblockingprofile:System Syscallblockingprofile:scheduler la tency Profile:调度延迟概述userdefined tasks:userdefined Regions:用户定义区域minimumutatorutilization:minimutator Utilization

Schedulerlatencyprofile

在查看问题的开始，除非是显而易见的，否则，我们不应该一开始就在细节上纠缠，所以我们通常看& quotSchedulerlatencyprofile & quot首先，我们可以通过图表看到总体调用开销，如下所示：

演示程序比较简单，这里分两块，一块是轨迹本身，另一块是通道的发送和接收。

Goroutineanalysis

的第二步是& quotGoroutineanalysis & quot。通过这个函数，我们可以看到每个功能块中运行了多少个Goroutine，观察每个go routine的运行成本花在了哪个阶段。如下所示：

从上图我们可以看到有三个goroutine，分别是runtime.main，runtime/trace。Start.func1和main.main.func1那么他们做了什么呢？接下来，我们可以通过点击具体细节来观察它们。如下所示：

同时也可以看到目前Goroutine在整个调用时间中所占的比例，以及GC清理和GC暂停等待的一些开销。如果觉得不够，可以下载图表分析，相当于看了整个Goroutine运行时。这一块可以帮助我们很好的分析Goroutine运行时，我们可以知道它有多慢，然后决定下一步的调查方向。如下所示：

名称含义耗时执行时间执行时间3140nsNetworkWaitTime网络等待时间0nsSyncBlockTime同步阻塞时间0nsBlockingSyscallTime调用阻塞时间0 NSSchedulerwaitime调度等待时间14nsGCSweepingGC清理0nsGCPauseGC暂停0ns

Viewtrace

在对当前程序的Goroutine运行分布有了初步的了解之后，让我们通过& quot查看跟踪& quot，如下所示：

乍一看，相信有些朋友会比较尴尬。我们可以根据笔记逐一检查，如下：

时间线：显示执行的时间单位，间隔可以根据时间维度的不同进行调整。具体来说，可以执行shift？查看帮助手册。堆：显示执行过程中内存的分配和释放。parallel:显示执行过程中每个Goroutine运行阶段运行的协同数，包括GCWaiting、Runnable、Running三种状态。OS thread:显示执行过程中有多少线程在运行，包括调用Syscall(InSyscall)和运行两种状态。虚拟处理器：每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统核心的数量。Schedules and events:显示每个虚拟处理器上正在运行什么Goroutine，连接行为表示事件相关性。单击特定的Goroutine行为后，您可以看到其相关的详细信息。这一块很简单，大家实践一下就明白了。该文本解释如下：

Start:开始时间WallDuration: duration SelfTime:执行时间StartStackTrace:开始时的堆栈信息EndStackTrace:结束时的堆栈信息Incomingflow: Outgoingflow输入流：Precedingevents输出流。

：之前的事件Followingevents：之后的事件Allconnected：所有连接的事件

ViewEvents

我们可以通过点击ViewOptions-Flowevents、Followingevents等方式，查看我们应用运行中的事件流情况。如下：

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

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

结合实战

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

curlhttp://127.0.0.1:6060/debug/pprof/trace\?seconds\=20>trace.outgotooltracetrace.out

Viewtrace

你很快的看到了熟悉的List界面，然后不信邪点开了Viewtrace界面，如下：

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

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

这时候有经验的你心里已经有了初步结论，你可以继续追踪Viewtrace深入进去，不过我建议先鸟瞰全貌，因此我们再往下看“Networkblockingprofile”和“Syscallblockingprofile”所提供的信息，如下：

Networkblockingprofile

Syscallblockingprofile

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

总结

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

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

参考

https://about.sourcegraph.com/go/an-introduction-to-go-tool-trace-rhys-hiltnerhttps://www.itcodemonkey.com/article/5419.htmlhttps://making.pusher.com/go-tool-trace/https://golang.org/cmd/trace/https://docs.google.com/document/d/1FP5apqzBgr7ahCCgFO-yoVhk4YZrNIDNf9RybngBc14/pubhttps://godoc.org/runtime/trace

本文作者：煎鱼，原创授权发布