Go 博客

更强大的 Go 执行跟踪

Michael Knyszek
2024 年 3 月 14 日

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

跟踪的魔力在于它可以轻松地揭示程序中难以用其他方式看到的方面。例如,多个 goroutine 在同一个通道上阻塞的并发瓶颈可能很难在 CPU 分析中看到,因为没有可供采样的执行。但在执行跟踪中,缺少执行会非常清晰地显示出来,并且被阻塞的 goroutine 的堆栈跟踪会迅速指出罪魁祸首。

Go 开发人员甚至可以使用 任务区域日志 来为自己的程序添加跟踪,以将更高层级的关注点与更低层级的执行细节相关联。

问题

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

  • 跟踪的开销很大。
  • 跟踪扩展性不佳,并且可能会变得太大而无法分析。
  • 启动跟踪以捕获特定错误行为的时间通常不明确。
  • 由于缺乏用于解析和解释执行跟踪的公共包,只有最具冒险精神的 gophers 才能以编程方式分析跟踪。

如果您在过去几年中使用过跟踪,您很可能遇到过上述问题中的一个或多个。但我们很高兴地告诉您,在过去的两个 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))

如果您有任何反馈,无论是正面还是负面,请分享到 提案问题

跟踪读取器 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)

与飞行记录器一样,还有一个 提案问题,它将是一个留下反馈的好地方!

我们想特别感谢 Dominik Honnef,他很早就试用过这个 API,并提供了很棒的反馈,并且还为 API 添加了对旧版跟踪的支持。

感谢!

这项工作得以完成,在很大程度上得益于 诊断工作组 的帮助,该工作组在一年前由来自 Go 社区的利益相关者共同发起,并向公众开放。

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

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

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