runtime/trace 包[1]包含了一个强大的工具,可用于理解和调试 Go 程序。该功能允许我们在一段时间内对每个 goroutine 的执行进行跟踪。使用go tool trace 命令[2](或优秀的开源工具gotraceui[3]),我们就可以可视化和探索这些跟踪数据。

跟踪的魔力在于,它可以轻松揭示程序中一些通过其他方式很难发现的问题。例如,大量 goroutine 在同一个 channel 上阻塞导致的并发瓶颈,在 CPU 分析中可能很难发现,因为没有执行(execution)需要采样。但在执行跟踪中,执行的缺失将被清晰地呈现,而阻塞 goroutine 的堆栈跟踪会快速指出问题所在。

Go 开发者甚至可以在自己的程序中使用Task[4]、Region[5]和Log[6]进行检测,从而将他们关注的高级问题与低级执行细节联系起来。

问题
不幸的是,执行跟踪中丰富的信息往往难以获取。历史上,以下四个主要问题一直阻碍着跟踪的使用:
1.跟踪开销很高。
2.跟踪的扩展性差,分析时可能会变得太大。
3.通常难以确定何时开始跟踪以捕获特定的错误行为。
4.由于缺乏解析和解释执行跟踪的公共包,只有最勇敢的 gopher 才能以编程方式分析跟踪。
如果你在过去几年使用过跟踪,可能会因上述一个或多个问题而感到沮丧。但我们很高兴地分享,在最近两个 Go 版本中,我们在这四个领域都取得了重大进展。

低开销跟踪
在 Go 1.21 之前,对许多应用程序而言,跟踪的运行时开销约在**10-20%**的 CPU 范围内,这限制了跟踪只能被选择性使用,而不能像CPU profiling那样持续使用。事实证明,跟踪的大部分成本归结于 traceback(跟踪回溯，在计算机编程中，它通常指的是程序运行时发生错误或异常时，系统生成的调用栈信息，用于帮助开发者定位问题的源头。)。运行时产生的许多事件都附带了堆栈跟踪,这对于实际识别关键执行时刻 goroutine 的行为是非常有价值的。

感谢Felix Geisendörfer和Nick Ripley在优化 traceback 效率方面所做的工作,执行跟踪的运行时 CPU 开销已经显著降低,对许多应用程序而言,降至 1-2%。你可以在 Felix 关于这个主题的精彩博文[7]中阅读更多相关工作的细节。

可扩展的跟踪
跟踪格式及其事件的设计侧重于相对高效的发送,但需要工具来解析并维护整个跟踪的状态。分析数百 MB 的跟踪可能需要几 GB 的内存!这个问题从根本上说是由于跟踪生成的方式造成的。为了保持运行时开销低,所有事件都被写入类似线程本地缓冲区。但这意味着事件出现的顺序与真实发生的顺序不一致,跟踪工具需要负担重任来弄清楚真正发生的情况。

在保持低开销的同时使跟踪可扩展的关键在于,偶尔分割正在生成的跟踪。每个分割点的行为有点像同时禁用和重新启用跟踪。到目前为止的所有跟踪数据代表一个完整且独立的跟踪,而新的跟踪数据将无缝地从中断处继续。

你可能已经想到,解决这个问题需要反思和重写运行时中跟踪实现的大量基础部分[8]。我们很高兴地说,这项工作在 Go 1.22 中完成并现已正式推出。重写带来了许多良好的改进[9],包括对 go tool trace 命令的一些改进。如果你有兴趣,所有详细内容都在设计文档[10]中。

(注:go tool trace 仍会将整个跟踪加载到内存中,但对于由 Go 1.22+程序生成的跟踪,移除此限制[11]现已变为可行。)

飞行记录
假设你在开发一个 web 服务,一个 RPC 花费了非常长的时间。当你意识到 RPC 已经运行很久时,你无法在那时开始跟踪,因为导致请求变慢的根本原因已经发生并且没有被记录下来。有一种称为飞行记录(flight recording)的技术可以帮助解决这个问题,你可能已经在其他编程环境中接触过了。飞行记录的思路是持续开启跟踪,并一直保留最新的跟踪数据,以防万一。然后,一旦发生有趣的事情,程序就可以直接写出它所拥有的数据!

在可以分割跟踪之前,这基本上是行不通的。但由于低开销使得连续跟踪变得可行,而且现在运行时可以随时分割跟踪,因此实现飞行记录变得很直接。因此,我们很高兴地宣布在golang.org/x/exp/trace[12]包中提供了一个飞行记录器实验。

请尝试使用它!下面是一个设置飞行记录器来捕获长时间 HTTP 请求的示例,可以帮助你入门。

    // 设置飞行记录器
    fr := trace.NewFlightRecorder()
    fr.Start()

    // 设置和运行HTTP服务器
    var once sync.Once
    http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()

        // 干些事情
        doWork(w, r)

        // 盼到了长耗时请求，来个快照
        if time.Since(start) > 300*time.Millisecond {
            // 这里我们为了简化只做一次，实际上你可以做多次
            once.Do(func() {
                // 抓取快照
                var b bytes.Buffer
                _, err = fr.WriteTo(&b)
                if err != nil {
                    log.Print(err)
                    return
                }
                // 把快照写入文件
                if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
                    log.Print(err)
                    return
                }
            })
        }
    })
    log.Fatal(http.ListenAndServe(":8080", nil))

果您有任何反馈，无论是正面的还是负面的，请分享到提案问题[13]中！

跟踪读取器 API
随着对跟踪实现的重写,我们也努力清理了其他的跟踪内部组件,比如 go tool trace。这催生了一次尝试,目标是创建一个足够好的可共享跟踪读取器 API,使跟踪更易于访问。就像飞行记录器一样,我们很高兴地宣布,我们也有一个实验性的跟踪读取器 API,希望能与大家分享。它与飞行记录器位于同一个包中,即golang.org/x/exp/trace[14]。

我们认为它已经足够好,可以在此基础上构建东西了,所以请务必试用!下面是一个示例,它测量了由于等待网络而阻塞的 goroutine 阻塞事件的比例。

    // 开始从标准输入读取跟踪数据。
    r, err := trace.NewReader(os.Stdin)
    if err != nil {
        log.Fatal(err)
    }

    var blocked int
    var blockedOnNetwork int
    for {
        // 读取事件
        ev, err := r.ReadEvent()
        if err == io.EOF {
            break
        } else if err != nil {
            log.Fatal(err)
        }
        // 堆代码 duidaima.com
        // 处理它
        if ev.Kind() == trace.EventStateTransition {
            st := ev.StateTransition()
            if st.Resource.Kind == trace.ResourceGoroutine {
                id := st.Resource.Goroutine()
                from, to := st.GoroutineTransition()

                // 查找阻塞的goroutine, 统计计数
                if from.Executing() && to == trace.GoWaiting {
                    blocked++
                    if strings.Contains(st.Reason, "network") {
                        blockedOnNetwork++
                    }
                }
            }
        }
    }
    // 打印我们所需
    p := 100 * float64(blockedOnNetwork) / float64(blocked)
    fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)

就像飞行记录器一样,有一个提案问题[15]可以作为留下反馈的好地方!我们想特别提及 Dominik Honnef,他很早就试用了这个 API,提供了宝贵的反馈,并为 API 贡献了对旧版本跟踪的支持。

感谢!
这项工作能够完成,在很大程度上要感谢一年多前成立的诊断工作组[16]的帮助,该小组由来自 Go 社区各界的利益相关者组成,并向公众开放。我们要借此机会感谢在过去一年中定期参加诊断会议的社区成员:Felix Geisendörfer、Nick Ripley、Rhys Hiltner、Dominik Honnef、Bryan Boreham 和 thepudds。

你们所做的讨论、反馈和工作是我们走到今天这一步的关键推动力。再次感谢!

Go 官方博客:More powerful Go execution traces[17] by Michael Knyszek.

Reference
[1]runtime/trace 包: https://go.dev/pkg/runtime/trace
[2]go tool trace 命令: https://go.dev/pkg/cmd/trace
[3]gotraceui: https://gotraceui.dev/
[4]Task: https://go.dev/pkg/runtime/trace#Task
[5]Region: https://go.dev/pkg/runtime/trace#WithRegion
[6]Log: https://go.dev/pkg/runtime/trace#Log
[7]精彩博文: https://blog.felixge.de/reducing-gos-execution-tracer-overhead-with-frame-pointer-unwinding/
[8]反思和重写运行时中跟踪实现的大量基础部分: https://go.dev/issue/60773
[9]重写带来了许多良好的改进: https://go.dev/doc/go1.22#runtime/trace
[10]设计文档: https://github.com/golang/proposal/blob/master/design/60773-execution-tracer-overhaul.md
[11]移除此限制: https://go.dev/issue/65315
[12]golang.org/x/exp/trace: https://go.dev/pkg/golang.org/x/exp/trace#FlightRecorder
[13]提案问题: https://go.dev/issue/63185
[14]golang.org/x/exp/trace: https://go.dev/pkg/golang.org/x/exp/trace#Reader
[15]提案问题: https://go.dev/issue/62627
[16]诊断工作组: https://go.dev/issue/57175
[17]More powerful Go execution traces: https://go.dev/blog/execution-traces-2024