0%

go trace 实现机制简析

前言

早听说 go 语言有完善的调试分析工具:pprof 和 trace。

  1. pprof 之前接触过,有了基本的了解。以我的理解,pprof 主要适用于 CPU,内存,这种资源使用的分析,属于资源使用视角。
  2. trace 最近才有了一些了解,以我的理解,trace 属于行为视角,记录的程序运行过程中的关键行为。

最近碰到一个 cgo 场景下,trace 不可用的问题,具体跟这个 issue #29707 描述的一样,解析 trace 文件的时候失败了。
因此了解了一下 trace 的实现机制,整体感觉下来,确实很牛,很精巧。

经过一番苦战,给 go 贡献了这个 CL 411034 ,以及有了这篇文章。

Trace 是干嘛的

之前看过一些文章,介绍如何使用 trace,看完之后还是一头雾水 …
了解了实现机制之后,则容易理解多了。

Go trace 跟其他的应用服务中的 trace 是类似的,比如现在很流行的分布式调用 trace,理念上是一样的,只是追踪的对象不一样。
分布式 trace,追踪的是请求的处理流程;go trace 追踪的是 go runtime 感知到的关键运行流程,比如 goroutine 执行流程,GC 执行流程,等。

Go trace 实现,主要是两个环节:

  1. 程序运行时,将一些关键的 event 记录下来,生成一个 trace 文件。
  2. 解析 trace 文件,用于分析程序的运行过程。

记录 event

trace 主要记录的是 goroutine 的一些关键状态变化事件,还有 GC 的状态变化事件,等等,一共有 48 个事件。

贴一部分出来,感受一下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
traceEvProcStart    = 5  // start of P
traceEvProcStop = 6 // stop of P
traceEvGCStart = 7 // GC start
traceEvGCDone = 8 // GC done
traceEvGCSTWStart = 9 // GC STW start
traceEvGCSTWDone = 10 // GC STW done
traceEvGCSweepStart = 11 // GC sweep start
traceEvGCSweepDone = 12 // GC sweep done
traceEvGoCreate = 13 // goroutine creation
traceEvGoStart = 14 // goroutine starts running
traceEvGoEnd = 15 // goroutine ends
traceEvGoStop = 16 // goroutine stops (like in select{})
traceEvGoSched = 17 // goroutine calls Gosched
traceEvGoPreempt = 18 // goroutine is preempted
traceEvGoSleep = 19 // goroutine calls Sleep
traceEvGoBlock = 20 // goroutine blocks
traceEvGoUnblock = 21 // goroutine is unblocked

总体来而,包括了 goroutine 从开始到结束,以及 GC 从开始到结束,这类重要流程中的关键节点。

具体实现上而言,以 goroutine 创建为例,核心代码代码如下:

1
2
3
4
5
6
7
func newproc1(fn *funcval, callergp *g, callerpc uintptr) *g {
// ...
if trace.enabled {
traceGoCreate(newg, newg.startpc)
}
// ...
}

意思是,创建协程的时候,如果 trace 是开启的,则记录一个 traceEvGoCreate = 13 的 event。

每个 event 可能还有一些不同的参数,大部分都有 timestamp,有些还有当时的调用栈。
比如,协程创建的 event,则包含了这么几个参数 [timestamp, new goroutine id, new stack id, stack id]
时间戳,新创建的 goroutine id,新协程的调用栈,当前协程的调用栈(调用栈都用一个数字 ID 表示,具体的栈内容另外存,以减少存储空间)。

记录 trace event,发生在被追踪程序运行时,所以需要尽量少的开销(虽然开销肯定是不小的,通常百分之几十的性能损耗)。
所以这期间,尽量只做必要的记录,剩下的事情,被放到了之后的阶段。

解析 trace 文件

拿到了原始的 trace 文件,还是需要做一些预处理的,以便后续的分析。这次碰到的 bug,就是发生在这个阶段。

其中预处理有一个很重要的环节,就是做 goroutine 的 event 进行逻辑上的排序。
逻辑上的排序,也就是按照 goroutine event 执行的逻辑先后关系排序(比如先创建了,然后才能执行),而不是简单的通过时间戳来排序。
因为 go 是多线程并发的,同一个 g 也可能切换在不同的 M/P 上去执行,并且不同的线程上产生的时间不一定可靠,所以不能简单依赖时间戳来排序。

解析完毕之后,我们可以得到每个 goroutine 的完整执行过程,从出生到死亡,包括了中间各种的状态变化,比如进/出系统调用,以及各种被阻塞的事件。

分析运行过程

有了完整的执行过程,要怎么分析,其实是严格限定的,只是 go 语言大佬们,提供一些常用的分析方式。

比如:

  1. View trace:查看所有 goroutine 的执行流,全局视图
  2. Goroutine analysis:主要是查看某个 goroutine 执行情况
  3. Network blocking profile:专门分析网络阻塞
  4. Synchronization blocking profile:专门分析同步阻塞
  5. Syscall blocking profile:专门分析系统调用阻塞
  6. Scheduler latency profile:专门分析调度延迟

这些是在解析 trace 文件之后,有对应的分析逻辑,来提供一套可视化的界面数据用于分析。
如果有必要,也可以自己实现一个适用的分析逻辑/界面。

具体每一个的用法,我也不太熟,不过好在有不少的分享文章了,懂了底层原理之后,去看这种分享使用的文章,就更容易理解了。

动态开启

因为开启 trace 记录 event 有比较大的开销,所以 trace 也不会一直开着,偶尔有棘手的问题需要调试的时候,才会动态开启。

在这方面,go 做得还是挺方便的,如果启用了 net/http/pprof,可以直接动态开启得到一个 trace 文件,比如:

1
curl http://127.0.0.1:6060/debug/pprof/trace?seconds=10

具体实现上来说,有两个关键点:

  1. 先来一个 STW,遍历当前所有的 goroutine,产生对应的前置 event,把 goroutine 的创建,到目前状态所依赖的 event 给补上(这样保证每个 goroutine 都有出生的 event)
  2. 然后,标记 trace.enabled = true,此后各个 hook 点的判断条件 if trace.enabled,就开始生效了,陆续开始生产 event 了。

是的,即使没有开启 trace,hook 点的条件判断还是会跑的,只是由于 CPU 的分支预测,这点开销基本是可以忽略不计的了。
个人拍脑袋估计,即使去掉了这个判断条件,万分之一的提升都不一定有。go 在这种便利性和微弱的性能提升之间的取舍,我还是蛮喜欢的。
go 中可以看到类似很多的这种取舍,比如在 c 中会通过宏开启的 assert 检查,go 直接就给默认开启了。(不过 go 也没有宏 …)

PS:这次的 bug,就是因为 cgo 中,extra M 上的 g,缺少了一些前置的 event,导致 goroutine event 的排序没法完成。

最后

了解一番之后,go trace 实现机制其实也简单,就是将 go 程序中的关键事件给记录下来,用于事后的分析。
这个角度看,跟我们日常用的打印日志调试也没有太大区别。

不过 trace 厉害的点在于它的完备性,便捷性,针对 go 语言层面可以感知的(比如 goroutine,GC)记录的信息是完备的,因此还可以进行逻辑推理。
也就是把大佬们的知识/经验,沉淀到这套 trace 系统里了(这个点上,跟平常业务系统用的 trace 又有异曲同工之妙)。
不需要平常临时加日志那样,少了一些日志还需要再加一轮 …

另外呢,也因为关键事件全部都记录下来了,信息量还是很大的,由此可以衍生出的分析方法也是非常之多的。
等哪天有机会体会了一把,或许也可以再来分享一些体会。