豆浆大叔
0%

go trace 实现机制简析

Posted on

前言

早听说 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 又有异曲同工之妙）。
不需要平常临时加日志那样，少了一些日志还需要再加一轮 …

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