Go 1.22 提供的更加强大的 Tracing 能力

本文是由 Go Team 的 Michael Knyszek 在 2024年3月14日发表于 go official blog，原文地址：https://go.dev/blog/execution-traces-2024

runtime/trace package

runtime/trace^[1] package包含了理解并排查 Go 程序的强大工具。其功能可以生成每个 goroutine 在一段时间内的执行追踪。通过使用 go tool trace^[2] 命令（或优秀的开源 gotraceui^[3]工具），你可以可视化并探索这些追踪中的数据。

Trace 的优势在于它可以很容易展示出程序中难以以其他方式看到的问题。例如，许多 goroutine 阻塞在同一通道上的并发瓶颈可能在 CPU 分析中很难看到，因为根本没有执行可供采样。但在执行追踪中，许多堆栈可以清晰度显示出来，并且阻塞的 goroutine 的堆栈跟踪将迅速指向罪魁祸首。

Go 开发者甚至能够使用 task^[4]、regions^[5]和 logs^[6] 来对他们自己的程序进行工具化，他们可以使用这些来将他们的高级关注点与低级执行细节相关联。

存在的问题

不幸的是，执行追踪中的丰富信息常常难以获得。历史上，追踪存在四个主要问题。

1. 追踪有高开销。
2. 追踪没有很好地扩展，并且可能变得太大而无法分析。
3. 通常不清楚何时开始追踪以捕获特定的不良行为。
4. 只有一部分 gopher 能够程序化地分析追踪，因为缺乏通用的公共包来解析和解释执行追踪。

如果你在过去几年中使用过追踪，你很可能因为这些问题中的一个或多个而感到沮丧。但我们很高兴地分享，在过去两个 Go 版本中，我们在所有这四个领域都取得了巨大进展。

低开销追踪

在 Go 1.21 之前，追踪的运行时开销对于许多应用程序来说在 10-20% 的 CPU 之间，这限制了追踪的使用情况，而不是像 CPU 分析那样的持续使用。事实证明，追踪成本的很大一部分来自于回溯。运行时产生的许多事件都附有堆栈跟踪，这对于实际识别 goroutine 在关键时刻正在做什么非常有价值。

得益于 Felix Geisendörfer 和 Nick Ripley 在优化回溯效率方面的工作，执行追踪的运行时 CPU 开销已经大幅降低，对于许多应用程序降至 1-2%。你可以在 Felix 关于此主题的优秀博客文章^[7]中阅读更多关于这项工作的内容。

可扩展追踪

追踪格式及其事件的设计围绕相对高效的发射，但需要工具来解析并保留整个追踪的状态。几百 MB 的追踪可能需要几个 Gi B的 RAM 来分析！

这个问题不幸地是追踪生成方式的基本问题。为了保持运行时开销低，所有事件都被写入相当于线程本地缓冲区的地方。但这意味着事件以非真实顺序出现，追踪工具需要弄清楚真正发生了什么。

使追踪在保持开销低的同时扩展的关键见解是偶尔分割正在生成的追踪。每个分割点的行为有点像同时禁用和重新启用一个goroutine中的追踪。到目前为止的所有追踪数据将代表一个完整且自包含的追踪，而新的追踪数据将无缝地从它离开的地方继续。

正如你所能想象的，修复这个问题需要重新思考和重写运行时追踪实现的许多基础。我们很高兴地说，这项工作已经在 Go 1.22 中落地，并且现在普遍可用。重写带来了许多不错的改进，包括对 go tool trace 命令的一些改进。如果你好奇，所有细节都在设计文档^[8]中。

（注：go tool trace仍然将完整追踪加载到内存中，但为由 Go 1.22+ 程序生成的追踪去除这个限制^[9]现在是可行的。）

飞行记录

假设你在处理一个web服务，一个 RPC 花费了很长时间。你不能在你知道 RPC 已经花费了很长时间的点开始追踪，因为慢请求的根本原因已经发生了，并没有被记录。

有一种称为飞行记录的技术可以帮助解决这个问题，你可能已经从其他编程环境中熟悉了它。飞行记录的见解是持续开启追踪，并始终保留最近的追踪数据，以防万一。然后，一旦发生有趣的事情，程序就可以简单地写入它所拥有的任何东西！

在追踪可以分割之前，这几乎是不可能的。但是，由于连续追踪现在由于低开销而变得可行，并且运行时现在可以在任何需要的时候分割追踪，事实证明实现飞行记录是直接的。

因此，我们很高兴地宣布一个飞行记录器实验，可在 golang.org/x/exp/trace^[10]包中使用。

请尝试它！以下是设置飞行记录器以捕获长时间 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))

如果你有任何反馈，无论是积极的还是消极的，请分享到提案 issue 上！

Trace reader API

随着追踪实现的重写，也进行了清理其他追踪内部的工作，比如go tool trace。这催生了一个尝试，创建一个足够好的追踪读取器API，以便共享，并可以使追踪更加易于访问。

就像飞行记录器一样，我们也很高兴地宣布我们还有一个实验性的追踪读取器API，我们想分享。它与飞行记录器在同一个包中，golang.org/x/exp/trace。

我们认为它足够好，可以开始在其上构建东西，所以请尝试它！以下是测量阻塞事件中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)
    }

    // 处理它。
    if ev.Kind() == trace.EventStateTransition {
        st := ev.StateTransition()
        if st.Resource.Kind == trace.ResourceGoroutine {
            from, to := st.Goroutine()

            // 查找阻塞的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)

我们想快速提到 Dominik Honnef，他早期尝试了它，提供了很好的反馈，并为API贡献了对旧版本追踪的支持。