Go 工程师必学:Go 大杀器之跟踪剖析 trace

2021年09月15日 阅读数:1
这篇文章主要向大家介绍Go 工程师必学:Go 大杀器之跟踪剖析 trace,主要内容包括基础应用、实用技巧、原理机制等方面,希望对大家有所帮助。

你们好,我是煎鱼。git

‍‍‍‍‍‍‍‍‍前段时间分享了《Go 程序崩了?煎鱼教你用 PProf 工具来救火!》,但有时候单单使用 pprof 还不必定足够完整观查并解决问题,由于在真实的程序中还包含许多的隐藏动做,例如:github

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

这些东西用 pprof 是很难分析出来的,但若是你又想知道上述的答案的话,你能够用本章节的主角 go tool trace 来打开新世界的大门。golang

一块儿愉快地开始吸鱼之路。面试

初步了解

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

查看可视化界面:segmentfault

图片

  • 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 运行分布有了初步了解后,咱们再经过 “查看跟踪” 看看之间的关联性,以下:

图片

这个跟踪图粗略一看,相信有的小伙伴会比较懵逼,咱们能够依据注解一块块查看,以下:

  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” 所提供的信息。

网络阻塞概况

图片

系统调用阻塞概况

图片

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

这时候咱们就能够接下进行下一步的排查和修改了。

总结

经过本文咱们习得了 go tool trace 的武林秘籍,它可以跟踪捕获各类执行中的事件,例如:

  • Goroutine 的建立/阻塞/解除阻塞。
  • Syscall 的进入/退出/阻止,GC 事件。
  • Heap 的大小改变。
  • Processor 启动/中止等等。

但愿你可以用好 Go 的两大杀器 pprof + trace 组合,此乃排查好搭档,谁用谁清楚,即便他并非绝对的万能。

如有任何疑问欢迎评论区反馈和交流,最好的关系是互相成就,各位的点赞就是煎鱼创做的最大动力,感谢支持。

文章持续更新,能够微信搜【脑子进煎鱼了】阅读,回复【 000】有我准备的一线大厂面试算法题解和资料。
本文 GitHub github.com/eddycjy/blog 已收录,欢迎 Star 催更。