原文地址：Golang大杀器追踪分析traceGo中有很多分析工具。之前写过一篇文章《Golang 大杀器之性能剖析 PProf》介绍PProf。如果有兴趣，可以访问我的博客。但是单独使用PProf有时并不一定足够完整，因为在真实的程序中有很多隐藏的动作，比如Goroutine在执行过程中会做哪些操作？它执行/阻塞多长时间？什么时候封锁？哪里堵了？谁再次锁定/解锁它们？GC如何影响Goroutine的执行？这些东西用PProf很难分析，但是如果你想知道上面的答案，可以使用本文的主角，gotooltrace，打开新世界的大门。目录如下：初步认识{ch<-"EDDYCJY"}()<-ch}生成trace文件：$gorunmain.go2>trace.out启动可视化界面：$gotooltracetrace.out2019/06/2216:14:52解析trace...2019/06/2216:14:52拆分trace...2019/06/2216:14:52打开浏览器。Traceviewer正在监听http://127.0.0.1:57321查看可视化界面：Viewtrace：查看traceGoroutine分析：Goroutine分析Networkblockingprofile：网络阻塞profileSynchronizationblockingprofile：同步阻塞profileSyscallblockingprofile：系统调用blockingprofileSchedulerlatencyprofile:SchedulingdelayprofileUserdefinedtasks:用户定义任务Userdefinedregions:用户定义区域定义区域Minimummutatorutilization:最小mutatorutilizationSchedulerlatencyprofile当你第一次检查问题时，除非它是一个明显的现象，一开始不要纠结细节，所以我们一般先查看“Schedulerlatencyprofile”，我们可以通过Graph看到整体的调用开销，如下：demo程序比较简单，所以有这里有两块，一块是trace本身，另一块是channel的发送和接收。Goroutine分析的第二步，看《Goroutine分析》。通过这个函数，我们可以看到整个运行过程中每个功能块中运行了多少个Goroutine，观察每个Goroutine的运行开销是在哪个阶段花费的。如下：从上图中我们可以看到有3个goroutines，分别是runtime.main、runtime/trace.Start.func1、main.main.func1，那么它是干什么的，然后我们可以点击具体细节来查看观察。如下：同时还可以看到当前Goroutine占整个调用时间的比例，以及GC清理和GC暂停等待的一些开销。如果觉得还不够，可以下载图表分析一下，相当于把整个Goroutineruntime拆了。这一块可以很好的帮助我们分析Goroutine运行时阶段，可以知道它到底慢在哪里。然后决定下一步的调查方向。如下：名称含义耗时ExecutionTime执行时间3140nsNetworkWaitTime网络等待时间0nsSyncBlockTime同步阻塞时间0nsBlockingSyscallTime调用阻塞时间0nsSchedulerWaitTime调度等待时间14nsGCSweepingGC清扫0nsGCPauseGCpause0nsViewtraceisrunningdistributionontheGoroutine对当前程序有了初步了解后，我们通过“ViewTracking”来看一下它们之间的关联，如下：根据注释，如下：Timeline：显示执行的时间单位，可以根据时间维度调整间隔。具体来说，你可以执行shift+?查看帮助手册。堆：显示执行期间的内存分配和释放。Coroutine：显示在执行过程中每个Goroutine运行阶段有多少个协程在运行，包括三种状态：GC等待（GCWaiting）、可运行（Runnable）和运行（Running）。OS线程：显示执行过程中有多少线程在运行，包括调用系统调用（InSyscall）和运行（Running）两种状态。VirtualProcessor：每个虚拟处理器显示一行，虚拟处理器数一般默认为系统核心数。CoroutinesandEvents：显示每个虚拟处理器上运行的Goroutines，而wirebehavior表示事件关联。点击特定的Goroutine行为后，可以看到其关联的详细信息。这一块很简单，实际操作一下就明白了。文中解释如下：Start：开始时间WallDuration：持续时间SelfTime：执行时间StartStackTrace：开始时的堆栈信息EndStackTrace：结束时的堆栈信息Incomingflow：输入流Outgoingflow：输出流Precedingevents:beforeFollowingevents:后续事件Allconnected:所有连接的事件ViewEvents我们可以通过点击ViewOptions-Flowevents,Followingevents等来查看我们应用运行的事件流。如下：通过分析图上的事件流，可以知道这个程序是从G1runtime.main开始运行的，运行时会创建2个Goroutines，先创建G18runtime/trace.Start.func1，再创建G19main。主要的。func1.同时我们可以通过它的GoroutineName来了解它的调用类型，比如：runtime/trace.Start.func1就是在程序中的main.main中调用了runtime/trace.Start方法，然后就是这个方法使用协程创建一个Closurefunc1来调用。这里，如果结合一开始的代码来看，很明显就是ch的输入输出的过程。结合实战，今天生产环境突然出现问题。你已经埋下了“net/http/pprof”这个神器，赶紧执行了如下命令：curlhttp://127.0.0.1:6060/debug/pprof/trace?seconds=20>trace.outgotooltracetrace.outViewtrace你很快就看到了熟悉的List界面，不信你再打开Viewtrace界面，如下：你彻底糊涂了，等等，是的在合适的区域执行快捷键W，不断缩放在时间线上，如下：经过初步调查，你发现上面的G大部分都和google.golang.org/grpc.(*Server).Serve.func有关。由Serve触发的大量相关操作。这时候如果你有经验，心里已经有了初步的结论，可以继续追踪Viewtrace深入，不过我建议还是先鸟瞰一下，下面再往下看“网络阻塞配置文件”和“系统调用阻塞配置文件”提供的信息如下：涉及到的方法，很明显是有人忘记关闭客户端连接了，赶紧改吧。总结通过这篇文章，我们学会了gotooltrace的武林秘籍，可以跟踪捕获执行中的各种事件，比如Goroutine创建/阻塞/解除阻塞，Syscall进入/退出/阻塞，GC事件，Heap大小变化，Processorstart/stopetc希望大家好好利用Go的两大杀手pprof+trace的组合。这是调查的好伙伴。谁用谁就知道，哪怕他不是万能的。参考https://about.sourcegraph.com...https://www.itcodemonkey.com/...https://making.pusher.com/go-...https://golang.org/cmd/trace/https://docs.google.com/docum...https://godoc.org/runtime/trace
