更强力的 Go 运行时 trace

本文是对 Go 官方博客 More powerful Go execution traces 的翻译。

runtime/trace 包包含了一个强大的工具, 用于理解和排查Go程序的问题。该功能允许生成在某段时间内每个goroutine 执行的 trace 记录。通过 go tool trace 命令(或优秀的开源工具 gotraceui ), 就可以可视化并探索这些 trace 记录中的数据。

trace 记录的神奇之处在于, 它可以轻松地揭示在其他情况下很难发现的程序行为。例如, 并发瓶颈导致许多goroutine 在同一个通道上阻塞, 这在CPU性能分析中可能很难看出来, 因为没有可执行代码被采样。但在执行追踪中, 执行的缺失将非常清晰地显示出来, 而且被阻塞的 goroutine 的堆栈跟踪也会快速指出问题的原因。

Go开发者甚至可以在自己的程序中植入tasks、regions 和 logs, 用于将他们关注的高级问题与低级执行细节相关联。

问题是:

不幸的是, 执行追踪中丰富的信息往往难以获取。以下四大问题一直阻碍了 trace 的使用:

trace 开销很高。
trace 记录缩放能力差,可能会变得太大无法分析。
通常不清楚应该在何时开始 trace 以捕获特定的异常行为。
由于缺乏解析和解释执行 trace 的公共包,只有最勇敢的Go程序员才能以编程方式分析追踪。

如果你在过去几年使用过 trace ,可能会对其中一个或多个问题感到沮丧。但我们很高兴地告诉大家,在最近两个Go版本中,我们在上述四个领域都取得了重大进展。

低开销追踪

在 Go 1.21之前, 对许多应用程序而言, trace 的运行时开销在 10-20% 的CPU之间, 这限制了 trace 只能在特定情况下使用, 而无法像CPU profiling那样持续使用。事实证明, trace 的大部分成本归结于堆栈回溯。运行时产生的许多事件都附带了堆栈跟踪,这对于实际识别 goroutine 在关键执行时刻的操作是非常有价值的。

得益于Felix Geisendörfer 和 Nick Ripley 对优化堆栈回溯效率所做的工作, 执行 trace 的运行时CPU开销大幅降低,对许多应用程序而言下降到 1-2%。你可以在 Felix 关于这个主题的精彩博文中阅读更多相关工作的内容。

可扩展的追踪记录

trace 格式及其事件的设计旨在提高产生效率, 但需要工具来解析和维护整个 trace 记录的状态。分析数百MB的追踪记录可能需要数GB的内存!

不幸的是, 这个问题是 trace 生成方式的基本问题。为了保持运行时开销低,所有事件都被写入类似线程本地缓冲区。但这意味着事件出现的顺序与真实顺序不一致,分析 trace 的工具必须弄清楚实际发生的情况。

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

你可能已经想到, 解决这个问题需要重新思考和重写运行时中 trace 实现的很多基础部分。我们很高兴地说,这项工作已在 Go 1.22 中落地, 现在可以普遍使用了。重写带来了许多优秀的改进, 包括对go tool trace命令的一些改进。如果你有兴趣,所有细节都在设计文档中。

(注: go tool trace 仍会将整个 trace 记录加载到内存中, 但现在可以为 Go 1.22+ 程序生成的 trace 记录移除此限制。)

飞行记录

假设你在开发一个Web 服务, 某个RPC调用花费了很长时间。你无法在意识到 RPC 已经运行一段时间时开始 trace,因为导致请求变慢的根本原因已经发生,并且没有被记录下来。

有一种称为飞行记录(flight recording)的技术可以帮助解决这个问题, 你可能已经在其他编程环境中熟悉它了。飞行记录的思路是持续进行 trace, 并始终保留最近的 trace 数据, 以防万一。然后, 一旦发生有趣的事情,程序只需将它所拥有的数据写出即可!

在追踪记录可以分割之前, 这几乎是行不通的。但由于低开销使持续 trace变得可行,并且运行时现在可以在任何需要时分割 trace,因此实现飞行记录是直接了当的。

因此,我们很高兴地宣布, golang.org/x/exp/trace 包中提供了一个飞行记录器实验。

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

// Set up the flight recorder.
fr := trace.NewFlightRecorder()
fr.Start()

// Set up and run an HTTP server.
var once sync.Once
http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
    start := time.Now()

    // Do the work...
    doWork(w, r)

    // We saw a long request. Take a snapshot!
    if time.Since(start) > 300*time.Millisecond {
        // Do it only once for simplicity, but you can take more than one.
        once.Do(func() {
            // Grab the snapshot.
            var b bytes.Buffer
            _, err = fr.WriteTo(&b)
            if err != nil {
                log.Print(err)
                return
            }
            // Write it to a file.
            if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
                log.Print(err)
                return
            }
        })
    }
})

log.Fatal(http.ListenAndServe(":8080", nil))

如果你有任何正面或负面的反馈, 请在建议的 issue 中分享!

追踪读取器API

伴随着重写 trace 实现的工作, 我们努力清理了其他 trace 内部机制,比如 go tool trace。这催生了一次尝试,旨在创建一个足够好的 trace 读取器API,可以共享并使 trace 更易访问。

就像飞行记录器一样,我们很高兴地宣布,我们也有一个实验性的trace 读取器API, 我们希望能够分享。它与飞行记录器位于同一个包中,即 golang.org/x/exp/trace 。

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

// Start reading from STDIN.
r, err := trace.NewReader(os.Stdin)
if err != nil {
    log.Fatal(err)
}

var blocked int
var blockedOnNetwork int
for {
    // Read the event.
    ev, err := r.ReadEvent()
    if err == io.EOF {
        break
    } else if err != nil {
        log.Fatal(err)
    }

    // Process it.
    if ev.Kind() == trace.EventStateTransition {
        st := ev.StateTransition()
        if st.Resource.Kind == trace.ResourceGoroutine {
            id := st.Resource.Goroutine()
            from, to := st.GoroutineTransition()

            // Look for goroutines blocking, and count them.
            if from.Executing() && to == trace.GoWaiting {
                blocked++
                if strings.Contains(st.Reason, "network") {
                    blockedOnNetwork++
                }
            }
        }
    }
}
// Print what we found.
p := 100 * float64(blockedOnNetwork) / float64(blocked)
fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)

非常感谢!

这项工作能够完成,在很大程度上要归功于一年多前成立的诊断工作组的帮助,该工作组是 Go 社区各利益相关方之间的合作,并向公众开放。

我们想借此机会感谢过去一年里定期参加诊断会议的社区成员:Felix Geisendörfer、Nick Ripley、Rhys Hiltner、Dominik Honnef、Bryan Boreham和thepudds。

你们进行的讨论、提供的反馈和付出的努力,是我们能够取得今天成就的关键。再次感谢!

#Go

更强力的 Go 运行时 trace

https://blog.zhangliangliang.cc/post/go-execution-traces.html

作者

Bobby Zhang

发布于

2024年3月20日

许可协议

Go JSON patch 下一篇