大家好，我是建宇。?????????前段时间我分享了《Go 程序崩了？煎鱼教你用 PProf 工具来救火！》，但是有时候单独使用pprof并不一定足以完全观察和解决问题，因为在真实的程序中有很多隐藏的动作，例如：Goroutine在执行过程中会做哪些操作？Goroutine执行/阻塞多长时间？系统调用何时被阻止？哪里堵了？谁锁定/解锁Goroutine？GC如何影响Goroutine的执行？用pprof很难分析这些东西，但是如果你想知道上面的答案，可以使用本章的主角，gotooltrace，打开新世界的大门。让我们一起愉快地开启熏鱼之路吧。初步理解import("os""runtime/trace")funcmain(){trace.Start(os.Stderr)defertrace.Stop()ch:=make(chanstring)gofunc(){ch<-《Go语言编程之旅》}()<-ch}生成trace文件：$gorunmain.go2>trace.out启动可视化界面：$gotooltracetrace.out2019/06/2216:14:52解析trace...2019/06/2216:14:52拆分跟踪...2019/06/2216:14:52打开浏览器。Traceviewer正在监听http://127.0.0.1:57321查看可视化界面：Viewtrace:ViewtraceGoroutineanalysis:GoroutineanalysisNetworkblockingprofile:NetworkblockingprofileSynchronizationblockingprofile:同步阻塞profileSyscallblockingprofile:系统调用blockingprofileSchedulerlatencyprofile:SchedulingdelayprofileUserdefinedtasks:UserdefinedtasksUserdefinedregions:UserCustomAreaMinimummutatorutilization:MinimumMutatorUtilizationSchedulingLatencyProfile当第一次看问题时，你不应该陷入细节除非很明显。因此，我们通常先看“Schedulerlatencyprofile”，通过Graph可以看到整体的调用开销，如下：demo程序比较简单，所以这里分为两部分，一个是trace本身，以及另一个是通道的发送和接收。Goroutine分析的第二步是“Goroutine分析”。通过这个函数，我们可以看到在整个运行过程中，每个功能块中运行了多少个Goroutines。观察每个Goroutine的运行开销都花在了哪个阶段。如下：从上图我们可以看到一共有3个goroutine，分别是：runtime.main。运行时/trace.Start.func1。主要的。主要的。func1.他们做了什么？我们可以通过点击具体细节来观察。如下：同时还可以看到当前Goroutine占整个调用时间的比例，以及GC清理和GC暂停等待的一些开销。如果觉得还不够，可以下载图表分析一下，相当于把整个Goroutineruntime拆了。这一块可以很好的帮助我们分析Goroutine运行时阶段，可以知道它到底慢在哪里。然后决定下一步的调查方向。如下：名称含义耗时执行时间执行时间3140nsNetworkWaitTime网络等待时间0nsSyncBlockTime同步阻塞时间0nsBlockingSyscallTime调用阻塞时间0nsSchedulerWaitTime调度等待时间14nsGCSweepingGCSweeping0nsGCPauseGCPausing0nsViewTrackingisrunningontheGoroutine对当前程序的分布有了初步了解后，我们可以通过“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:所有连接的事件查看事件我们可以通过点击ViewOptions-Flowevents,Followingevents等来查看我们应用运行的事件流，如下：通过分析图上的事件流，我们可以知道这个程序是从G1runtime.main开始运行的。2Goroutines在运行时创建：首先创建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.out$gotooltracetrace.out你很快就看到了熟悉的List界面，不信你再打开Viewtrace界面，如下：你彻底糊涂了，等等，在合适的区域按下快捷键W在时间轴上不断放大，如下：初步调查，你发现上面的G大部分都和google.golang.org/grpc.(*Server).Serve.func相关，一大串相关的动作是也由Serve触发。这时候，如果你有经验，心里已经有了一个初步的结论，可以继续追踪Viewtrace，深入下去。不过还是建议先鸟瞰一下，再看看“网络阻塞配置文件”和“系统调用阻塞配置文件”提供的信息。网络阻塞概述系统调用阻塞概述通过以上三项的跟踪分析，加上泄漏、阻塞时间、涉及的内部方法名，很明显是有人忘记关闭客户端连接。这时候我们就可以进行下一步的排查和修改了。总结通过这篇文章，我们学会了gotooltrace的武功秘籍，可以跟踪捕获各种执行事件，比如：Goroutine的创建/阻塞/解阻塞。系统调用进入/退出/阻塞，GC事件。堆的大小发生变化。Processorstart/stopetc希望大家好好利用Go的两大杀手pprof+trace的组合。这是调查的好伙伴。谁知道谁在使用它，即使他不是绝对无所不能。如有任何问题，欢迎在评论区反馈交流。最好的关系是相互成就。您的好评是创作炸鱼最大的动力。感谢您的支持。文章持续更新，可以微信搜索【脑补炸鱼】阅读，回复【000】有我准备的一线工厂面试的算法题和资料的解答和资料。本文已收录在GitHubgithub.com/eddycjy/blog，欢迎更新Star。
