原文在这里

由 Michael Knyszek 发布于2024年3月14日

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

跟踪的神奇之处在于它可以轻易揭示程序中难以通过其他方式发现的问题。例如,大量 Goroutines在同一个通道上阻塞可能在CPU分析中很难看到,因为没有执行来采样。但在执行跟踪中,未执行的内容将清晰地显示出来,而被阻塞的Goroutines的堆栈跟踪将迅速指向罪魁祸首。

gotooltrace

Go开发人员甚至能够用任务区域日志来检测他们自己的程序,这些任务、区域和日志可以将上层问题与低层执行细节相关联。

Issues

不幸的是,执行跟踪中的丰富信息往往难以获取。过去,跟踪存在四个主要问题。

  1. 跟踪的开销很高。
  2. 跟踪的规模难以控制,可能变得过大而无法分析。
  3. 往往不清楚何时开始跟踪以捕获特定的不良行为。
  4. 由于缺乏用于解析和解释执行跟踪的公共包,只有最有冒险精神的Gopher才能编程地分析跟踪。

如果你在过去几年中使用过跟踪,很可能会遇到其中一个或多个问题。但我们很高兴地宣布,在过去两个Go版本中,我们在所有这四个方面都取得了重大进展。

降低跟踪的开销

在Go 1.21之前,跟踪的运行时开销对许多应用程序来说大约在10–20%的CPU使用率之间,这限制了跟踪的使用,而不像CPU分析那样连续使用。事实证明,跟踪的成本很大程度上取决于回溯。运行时产生的许多事件都附带有堆栈跟踪,这些对于实际确定关键时刻的goroutines在执行过程中的行为非常宝贵。

得益于Felix Geisendörfer和Nick Ripley在优化回溯效率方面的工作,执行跟踪的运行时CPU开销已经大大降低,对于许多应用程序来说仅为1–2%。你可以在Felix关于此主题的博文中了解更多相关工作内容。

可扩展的跟踪

跟踪格式及其事件设计得相对高效,但需要工具来解析和保留整个跟踪的状态。几百MiB 字节的跟踪可能需要数十GiB字节的内存来进行分析!

不幸的是,这个问题基本上是跟踪生成方式的固有问题。为了保持运行时开销低,所有事件都被写入等同于线程本地缓冲区的位置。但这意味着如果事件出现的顺序不正确,那么跟踪工具必须弄清楚实际发生了什么。

使跟踪规模化并保持开销低的关键洞见是偶尔分割正在生成的跟踪。每个分割点的行为有点像同时禁用和重新启用跟踪。到目前为止,所有的跟踪数据都代表了一个完整且独立的跟踪,而新的跟踪数据会从上次中断的地方无缝继续。

正如你所想象的那样,解决这个问题需要重新考虑和重写运行时中跟踪实现的大部分基础。我们很高兴地宣布这项工作已于Go 1.22 中完成,并且现已普遍可用。随着重写,还带来了许多不错的改进,包括一些对go tool trace 命令的改进。如果你感兴趣,所有细节都在设计文档中。

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

飞行记录

假设你在一个网络服务上工作,一个远程过程调用(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可以使跟踪更易于访问。

就像飞行记录器一样,我们很高兴地宣布,我们还拥有一个试验性的跟踪读取器 API,我们希望与大家分享。它位于与飞行记录器相同的包中,即golang.org/x/exp/trace

我们认为它已经足够好了,可以开始在其上构建更多功能,请尝试一下吧!以下是一个示例,用于测量阻塞事件中在网络上等待的goroutines占比。

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

就像飞行记录器一样,我们期待你在提案问题中留下反馈意见!

我们需要感谢Dominik Honnef,他早早地尝试了这个工具,并提供了很好的反馈意见,并为API添加了对旧跟踪版本的支持。

致谢

这项工作的完成,很大程度上要归功于诊断工作组的帮助,这个工作组于一年多前由来自Go社区各方的利益相关者共同发起,对公众开放。

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

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


孟斯特

声明:本作品采用署名-非商业性使用-相同方式共享 4.0 国际 (CC BY-NC-SA 4.0)进行许可,使用时请注明出处。

Author: mengbin

blog: mengbin

Github: mengbin92

cnblogs: 恋水无意

腾讯云开发者社区:孟斯特