Go 工程师必学（Go 大杀器之跟踪剖析 trace） phpgolang后端

大家好，我是煎鱼。
?????????前段时间分享了《Go 程序崩了？煎鱼教你用 PProf 工具来救火！》，但有时候单单使用 pprof 还不一定足够完整观查并解决问题，因为在真实的程序中还包含许多的隐藏动作，例如：

Goroutine 在执行时会做哪些操作？
Goroutine 执行/阻塞了多长时间？
Syscall 在什么时候被阻止？在哪里被阻止的？
谁又锁/解锁了 Goroutine ？
GC 是怎么影响到 Goroutine 的执行的？

这些东西用 pprof 是很难分析出来的，但如果你又想知道上述的答案的话，你可以用本章节的主角 go tool trace 来打开新世界的大门。
一起愉快地开始吸鱼之路。
初步了解

import ( "os" "runtime/trace" )func main() { trace.Start(os.Stderr) defer trace.Stop() ch := make(chan string) go func() { ch <- "Go语言编程之旅" }() <-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 分析
第二步看 “Goroutine analysis”，我们能通过这个功能看到整个运行过程中，每个函数块有多少个有 Goroutine 在跑。
观察每个的 Goroutine 的运行开销都花费在哪个阶段。如下：

文章图片

通过上图我们可以看到共有 3 个 goroutine，分别是：

runtime.main。
runtime/trace.Start.func1。
main.main.func1。

它们都做了些什么事呢，我们可以通过点击具体细项去观察。如下：

文章图片

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

名称	含义	耗时
Execution Time	执行时间	3140ns
Network Wait Time	网络等待时间	0ns
Sync Block Time	同步阻塞时间	0ns
Blocking Syscall Time	调用阻塞时间	0ns
Scheduler Wait Time	调度等待时间	14ns
GC Sweeping	GC 清扫	0ns
GC Pause	GC 暂停	0ns

查看跟踪
在对当前程序的 Goroutine 运行分布有了初步了解后，我们再通过 “查看跟踪” 看看之间的关联性，如下：
【Go 工程师必学（Go 大杀器之跟踪剖析 trace）】

文章图片

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

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