Go 官方博客

更强大的 Go 执行跟踪

Michael Knyszek
14 March 2024

runtime/trace 包包含一个强大的工具，用于理解和排查 Go 程序的问题。其中的功能可以用于生成每个 goroutine 在一段时间内的执行跟踪。使用 go tool trace 命令（或优秀的开源 gotraceui 工具），可以可视化和探索这些跟踪数据。

跟踪的神奇之处在于它可以轻松揭示程序中通过其他方式难以看到的问题。例如，许多 goroutine 在同一通道上阻塞造成的并发瓶颈在 CPU profile 中可能很难看到，因为没有执行可以采样。但在执行跟踪中，执行的缺失会清晰地显示出来，并且阻塞 goroutine 的堆栈跟踪会迅速指向罪魁祸首。

Go 开发者甚至可以使用任务、区域和日志来检测自己的程序，他们可以用这些来关联更高层面的关注点和底层执行细节。

问题

不幸的是，执行跟踪中丰富的信息往往难以获取。跟踪的四个主要问题历来是阻碍。

跟踪的开销很高。
跟踪的可伸缩性不好，数据可能变得太大而无法分析。
通常不清楚何时开始跟踪才能捕获特定的不良行为。
鉴于缺乏用于解析和解释执行跟踪的公共包，只有最勇于探索的 Go 开发者才能以编程方式分析跟踪。

如果您在过去几年使用过跟踪，您可能曾因其中一个或多个问题而感到沮丧。但我们很高兴地告诉您，在过去的两个 Go 版本中，我们在这四个领域都取得了巨大进展。

低开销跟踪

在 Go 1.21 之前，对于许多应用程序来说，跟踪的运行时开销在 10-20% 的 CPU 之间，这将跟踪限制在情境使用，而不是像 CPU profile 那样持续使用。结果表明，跟踪的大部分开销归结于回溯（tracebacks）。运行时生成的许多事件都附带堆栈跟踪，这对于实际识别 goroutine 在执行关键时刻正在做什么非常有价值。

感谢 Felix Geisendörfer 和 Nick Ripley 在优化回溯效率方面所做的工作，执行跟踪的运行时 CPU 开销已大幅削减，对于许多应用程序来说降至 1-2%。您可以在 Felix 关于该主题的精彩博文中阅读更多关于此处完成的工作的信息。

可伸缩的跟踪

跟踪格式及其事件围绕相对高效的发出而设计，但需要工具来解析并保留整个跟踪的状态。几百 MiB 的跟踪可能需要几 GiB 的 RAM 才能分析！

不幸的是，这个问题是跟踪如何生成的根本原因。为了保持运行时开销低，所有事件都写入相当于线程本地缓冲区的区域。但这表示事件出现时并非按真实顺序排列，因此需要跟踪工具来确定实际发生的情况。

在保持开销低的同时使跟踪具有可伸缩性的关键在于偶尔分割正在生成的跟踪。每个分割点都像一次性禁用和重新启用跟踪一样。到目前为止的所有跟踪数据将代表一个完整且自包含的跟踪，而新的跟踪数据将无缝地从上次停止的地方开始。

正如您可能想象的那样，修复这个问题需要重新思考和重写运行时跟踪实现的基础。我们很高兴地告诉您，这项工作已在 Go 1.22 中实现并普遍可用。重写带来了许多不错的改进，包括对 go tool trace 命令的一些改进。如果您好奇，所有详细信息都在设计文档中。

(注意：go tool trace 仍然将完整跟踪加载到内存中，但取消此限制对于 Go 1.22+ 程序生成的跟踪现在是可行的。)

飞行记录

假设您正在开发一个 Web 服务，并且某个 RPC 花费了很长时间。您无法在知道 RPC 已经耗时很长时才开始跟踪，因为慢请求的根本原因已经发生并且未被记录下来。

有一种技术可以帮助解决这个问题，称为飞行记录 (flight recording)，您可能在其他编程环境中已经熟悉它。飞行记录的关键思想是持续开启跟踪，并始终保留最新的跟踪数据，以防万一。然后，一旦发生有趣的事情，程序就可以立即将拥有的数据写出！

在跟踪可以分割之前，这几乎是不可能的。但由于低开销使得持续跟踪现在可行，并且运行时现在可以在需要时分割跟踪，实现飞行记录就变得很简单了。

因此，我们很高兴宣布飞行记录器实验功能，该功能可在 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

随着跟踪实现的重写，还进行了一项清理其他跟踪内部的工作，例如 go tool trace。这催生了创建跟踪读取器 API 的尝试，该 API 足够好以供共享，并可以使跟踪更容易访问。

就像飞行记录器一样，我们很高兴宣布我们也有一个实验性的跟踪读取器 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 {
                from, to := st.Goroutine()

                // 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)

就像飞行记录器一样，有一个提案 issue 是留下反馈的好地方！

我们想特别感谢 Dominik Honnef，他是早期尝试者之一，提供了宝贵的反馈，并为 API 贡献了对旧跟踪版本的支持。

谢谢！

这项工作得以完成，很大程度上得益于诊断工作组成员的帮助。该工作组于一年前启动，是 Go 社区各利益相关者之间的合作，并向公众开放。

我们想花点时间感谢在过去一年中定期参加诊断会议的社区成员：Felix Geisendörfer、Nick Ripley、Rhys Hiltner、Dominik Honnef、Bryan Boreham、thepudds。

你们所有人的讨论、反馈和投入的工作对于我们今天取得的成就至关重要。谢谢！

下一篇文章：Go 开发者调查 2024 年上半年结果
上一篇文章：切片上的健壮泛型函数
博客索引