文章 标签 分类

Contents

Golang Trace

   396 words   2 minutes 

Go语言的trace包是一个用于追踪程序运行时信息的工具，它可以帮助开发者理解程序的运行时行为，诊断性能问题。trace包主要是通过分析程序生成的追踪文件来工作的。

runtime/trace 包含了一个强大的工具，用于理解和排查 Go 程序。它的功能允许我们生成一个时间段内每个 goroutine 的执行轨迹。通过使用 go tool trace 命令（或者优秀的开源工具 gotraceui），我们可以可视化并探索这些轨迹数据。

trace的魔力在于它能轻易揭示程序中那些以其他方式难以发现的事情。例如，一个并发瓶颈，许多 goroutine 在同一个 channel 上阻塞可能在 CPU 分析中很难看出，因为没有执行样本。但在执行trace中，执行链路的缺失将以惊人的清晰度显示出来，被阻塞的 goroutine 的堆栈追踪将迅速指向问题所在。

https://go.dev/blog/execution-traces-2024/gotooltrace.png

Go 开发者甚至可以使用任务、区域和日志来为他们的程序添加插桩，这样他们就能将自己的高层次关注点与底层执行细节相关联。

问题

不幸的是，执行trace中的丰富信息往往难以触及。历史上，与trace相关的四个大问题经常成为障碍：

  1. trace的开销很大。
  2. trace的扩展性不好，可能变得过于庞大而难以分析。
  3. 往往不清楚何时开始trace记录以捕获特定的错误行为。
  4. 鉴于缺乏用于解析和解释执行trace的公开包，只有最具冒险精神的 gophers 能够以编程方式分析trace。

如果你在过去几年中使用过trace，你可能因为这些问题中的一个或多个而感到沮丧。但在过去的两个 Go 版本中，Golang团队在这四个领域都取得了重大进展。

降低trace成本

在 Go 1.21 之前，许多应用程序的 trace 运行时开销大约在 10–20% CPU 之间，这限制了 trace 的使用场景，不能像 CPU profiling 那样持续使用。事实证明，trace 的大部分成本都归结于 traceback。由运行时产生的许多事件都附带了堆栈追踪，这对于实际识别 goroutine 在执行关键时刻的行为是无价的。

感谢 Felix Geisendörfer 和 Nick Ripley 在优化 traceback 效率方面的工作，执行 trace 的运行时 CPU 开销已经大幅度降低，对于许多应用程序而言，现在只有 1–2%。

可扩展Trace

trace 格式及其事件在设计时围绕着相对高效的发射进行，但需要工具来解析并保持 trace 全部状态。几百 MiB 的 trace 可能需要几 GiB 的 RAM 来分析！

不幸的是，这个问题是 trace 生成方式的根本问题。为了保持运行时开销低，所有事件都写入等同于线程局部缓冲区的东西。但这意味着事件出现的顺序并不是它们真正的顺序，解析真正发生了什么的负担落在了 trace 工具上。

让 trace 在保持低开销的同时能够扩展的关键洞见是偶尔分割正在生成的 trace。每个分割点的行为有点像同时禁用并重新启用 tracing。到目前为止的所有 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 之前，这几乎是行不通的。但是因为现在持续的 tracing 由于低开销而变得可行，加上运行时现在可以在需要时随时分割 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))

trace读取API

随着 trace 实现的重写，还有一项努力是清理其他 trace 内部实现，比如 go tool trace。这催生了尝试创建一个足够好以至于可以共享的 trace 读取 API，目的是使 trace 更加易于访问。

就像黑匣子一样，golang也有一个实验性的 trace 读取 API 。它在同一个包 golang.org/x/exp/trace 中可用。

golang团队认为它足够好，可以开始在其上构建东西，所以请尝试使用它！下面是一个示例，该示例测量等待网络的 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)
Updated on 2024-03-17
Back | Home