Go 博客

更强大的 Go 执行跟踪

Michael Knyszek
2024 年 3 月 14 日

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

跟踪的神奇之处在于,它可以轻松地揭示出其他方法难以发现的程序问题。例如,一个大量的 goroutine 阻塞在同一个通道上的并发瓶颈,在 CPU 剖析中可能很难发现,因为它没有可采样的执行。但在执行跟踪中,*缺乏* 执行会惊人地清晰地显示出来,阻塞的 goroutine 的堆栈跟踪会迅速指向罪魁祸首。

Go 开发者甚至可以使用 tasks、regions 和 logs 来检测自己的程序,这些可以用来将他们的高层关注点与底层执行细节关联起来。

问题

不幸的是,执行跟踪中丰富的信息往往是难以获得的。历史上,跟踪的四个主要问题一直阻碍着我们。

  • 跟踪的开销很高。
  • 跟踪扩展性不佳,可能变得太大而无法分析。
  • 要捕获特定的不良行为,通常不清楚何时开始跟踪。
  • 由于缺乏用于解析和解释执行跟踪的公共包,只有最勇于尝试的 Gopher 才能以编程方式分析跟踪。

如果您近几年来使用过跟踪,您很可能被这些问题中的一个或多个所困扰。但我们很高兴地宣布,在过去两个 Go 版本中,我们在所有这四个领域都取得了巨大进展。

低开销跟踪

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

得益于 Felix Geisendörfer 和 Nick Ripley 在优化回溯效率方面所做的工作,执行跟踪的运行时 CPU 开销已大大降低,对于许多应用程序而言,降至 1-2%。您可以在 Felix 关于此主题的精彩博客文章中阅读有关所做工作的更多信息。

可扩展的跟踪

跟踪格式及其事件被设计为相对高效地发出,但需要工具来解析并保留整个跟踪的状态。几百兆字节的跟踪可能需要几个千兆字节的 RAM 才能进行分析!

不幸的是,这个问题是跟踪生成方式的基本问题。为了保持低运行时开销,所有事件都写入等效于线程本地缓冲区。但这会使事件的出现顺序错乱,并将弄清楚实际发生情况的负担推给了跟踪工具。

使跟踪可扩展同时保持低开销的关键洞察是偶尔分割正在生成的跟踪。每个分割点都表现得有点像一次性禁用和重新启用跟踪。到目前为止的所有跟踪数据将代表一个完整且自包含的跟踪,而新的跟踪数据将无缝地接续下去。

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

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

飞行记录

假设您在一个 Web 服务上工作,一个 RPC 花费了很长时间。您无法在发现 RPC 已经花费很长时间时开始跟踪,因为导致请求缓慢的根本原因已经发生并且没有被记录下来。

有一种技术可以帮助解决这个问题,称为飞行记录,您可能已经从其他编程环境中熟悉它了。飞行记录的洞察是持续开启跟踪,并始终保留最新的跟踪数据,以备不时之需。然后,一旦发生有趣的事情,程序就可以写出它拥有的任何内容!

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

因此,我们很高兴地宣布一项飞行记录实验,它在 `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,我们想与之分享。它与飞行记录器在同一个包中,即 `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。

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

下一篇文章:2024 年上半年 Go 开发者调查结果
上一篇文章:对 slice 使用健壮的泛型函数
博客索引