import (
	"os"
	"runtime/trace"
)

func main() {
	trace.Start(os.Stderr)
	defer trace.Stop()

	ch := make(chan string)
	go func() {
		ch <- "EDDYCJY"
	}()

	<-ch
}

生成跟踪文件：

$ go run main.go 2> trace.out

启动可视化界面：

$ 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

查看可视化界面：

• View trace：查看跟踪
• Goroutine analysis：Goroutine 分析
• Network blocking profile：网络阻塞概况
• Synchronization blocking profile：同步阻塞概况
• Syscall blocking profile：系统调用阻塞概况
• Scheduler latency profile：调度延迟概况
• User defined tasks：用户自定义任务
• User defined regions：用户自定义区域
• Minimum mutator utilization：最低 Mutator 利用率

在刚开始查看问题时，除非是很明显的现象，否则不应该一开始就陷入细节，因此我们一般先查看 “Scheduler latency profile”，我们能通过 Graph 看到整体的调用开销情况，如下：

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

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

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

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

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

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

1. 时间线：显示执行的时间单元，根据时间维度的不同可以调整区间，具体可执行 shift + ? 查看帮助手册。
2. 堆：显示执行期间的内存分配和释放情况。
3. 协程：显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。
4. OS 线程：显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running）这两种状态。
5. 虚拟处理器：每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统内核数。
6. 协程和事件：显示在每个虚拟处理器上有什么 Goroutine 正在运行，而连线行为代表事件关联。

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

• Start：开始时间
• Wall Duration：持续时间
• Self Time：执行时间
• Start Stack Trace：开始时的堆栈信息
• End Stack Trace：结束时的堆栈信息
• Incoming flow：输入流
• Outgoing flow：输出流
• Preceding events：之前的事件
• Following events：之后的事件
• All connected：所有连接的事件

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

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

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

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

• curl http://127.0.0.1:6060/debug/pprof/trace?seconds=20 > trace.out
• go tool trace trace.out

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

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

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

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

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

我们来看一个如何使用这个工具跟踪典型问题的例子。

当完成关键任务的goroutine被阻止运行时，可能会引起延迟问题。 可能的原因有很多：做系统调用时被阻塞; 被共享内存阻塞（通道/互斥等）; 被runtime系统（例如GC）阻塞，甚至可能调度程序不像您想要的那样频繁地运行关键goroutine。

所有这些都可以使用go tool trace来识别。 您可以通过查看PROCs时间线来跟踪问题，并发现一段时间内goroutine被长时间阻塞。 一旦你确定了这段时间，应该给出一个关于根本原因的线索。

作为延迟问题的一个例子，让我们看看长时间的GC暂停：

红色的事件代表了唯一的程序goroutine正在运行。 在所有四个线程上并行运行的goroutines是垃圾收集器的MARK阶段。 这个MARK阶段阻止了主要的goroutine。 你能出到阻止runtime.main goroutine的时间长短吗？

在Go团队宣布GC暂停时间少于100微秒后,我很快就调查了这个延迟问题。 我看到的漫长的停顿时间，go tool trace的结果看起来很奇怪，特别是可以看到它们(暂停)是在收集器的并发阶段发生的。 我在go-nuts 邮件列表中提到了这个问题，似乎与这个问题有关，现在已经在Go 1.8中修复了。 我的基准测试又出现了另一个GC暂停问题，这在写本文时依然会出现。 如果没有go tool trace这一工具，我是无法完成调查工作的。

假设您已经编写了一个程序，您希望使用所有的CPU，但运行速度比预期的要慢。 这可能是因为您的程序不像您所期望的那样并行运行。 这可能是由于在很多关键路径上串行运行太多，而很多代码原本是可以异步（并行）运行的。

假设我们有一个pub/sub消息总线，我们希望在单个goroutine中运行，以便它可以安全地修改没有加互斥锁的用户map。 请求处理程序将消息写入消息总线队列。 总线从队列中读取消息，在map中查找订阅者，并将消息写入其套接字。 让我们看看单个消息的go tool trace中的内容：

最初的绿色事件是http处理程序读取发布的消息并将其写入消息总线事件队列。 之后，消息总线以单个线程运行 - 第二个绿色事件 - 将消息写给订阅者。

红线显示消息写入订户的套接字的位置。 写入所有订阅者的过程需要多长时间？

问题是四分之一的线程正在闲置。 有没有办法利用它们？ 答案是肯定的 我们不需要同步写入每个用户; 写入可以在单独的goroutine中同时运行。 让我们看看如果我们作出这个变化，会发生什么：

正如你所看到的，写给订阅者消息的过程正在许多goroutines的上同步进行。

但它是否更快？

有趣的是，鉴于我们使用4X的CPU，加速是适合的。 这是因为并行运行代码有更多的开销：启动和停止goroutines; 共享内存以及单独的缓存。 加速的理论上限使得我们无法实现4倍延迟降低：阿姆达尔定律。

实际上，并行运行代码往往效率较低; 特别是在goroutine是非常短暂的，或者他们之间有很多的竞争的情况下。 这是使用此工具的另一个原因：尝试这两种方法，并检查哪种工作最适合您的用例。

当然，go tool trace不能解决一切问题。 如果您想跟踪运行缓慢的函数，或者找到大部分CPU时间花费在哪里，这个工具就是不合适的。 为此，您应该使用go tool pprof，它可以显示在每个函数中花费的CPU时间的百分比。 go tool trace更适合于找出程序在一段时间内正在做什么，而不是总体上的开销。 此外，还有“view trace”链接提供的其他可视化功能，这些对于诊断争用问题特别有用。 了解您的程序在理论上的表现（使用老式Big-O分析）也是无可替代的。

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

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