更强大的Go执行跟踪能力

Go官方博客:More powerful Go execution traces by Michael Knyszek.

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

跟踪的魔力在于,它可以轻松揭示程序中一些通过其他方式很难发现的问题。例如,大量goroutine在同一个channel上阻塞导致的并发瓶颈,在CPU分析中可能很难发现,因为没有执行(execution)需要采样。但在执行跟踪中,执行的缺失将被清晰地呈现,而阻塞goroutine的堆栈跟踪会快速指出问题所在。

Go开发者甚至可以在自己的程序中使用Task、Region和Log进行检测,从而将他们关注的高级问题与低级执行细节联系起来。

问题

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

跟踪开销很高。
跟踪的扩展性差,分析时可能会变得太大。
通常难以确定何时开始跟踪以捕获特定的错误行为。
由于缺乏解析和解释执行跟踪的公共包,只有最勇敢的gopher才能以编程方式分析跟踪。

如果你在过去几年使用过跟踪,可能会因上述一个或多个问题而感到沮丧。但我们很高兴地分享,在最近两个Go版本中,我们在这四个领域都取得了重大进展。

低开销跟踪

在Go 1.21之前,对许多应用程序而言,跟踪的运行时开销约在10-20%的CPU范围内,这限制了跟踪只能被选择性使用,而不能像CPU profiling那样持续使用。事实证明,跟踪的大部分成本归结于traceback(跟踪回溯，在计算机编程中，它通常指的是程序运行时发生错误或异常时，系统生成的调用栈信息，用于帮助开发者定位问题的源头。)。运行时产生的许多事件都附带了堆栈跟踪,这对于实际识别关键执行时刻goroutine的行为是非常有价值的。

感谢Felix Geisendörfer和Nick Ripley在优化traceback效率方面所做的工作,执行跟踪的运行时CPU开销已经显著降低,对许多应用程序而言,降至1-2%。你可以在Felix关于这个主题的精彩博文中阅读更多相关工作的细节。

可扩展的跟踪

跟踪格式及其事件的设计侧重于相对高效的发送,但需要工具来解析并维护整个跟踪的状态。分析数百MB的跟踪可能需要几GB的内存!

这个问题从根本上说是由于跟踪生成的方式造成的。为了保持运行时开销低,所有事件都被写入类似线程本地缓冲区。但这意味着事件出现的顺序与真实发生的顺序不一致,跟踪工具需要负担重任来弄清楚真正发生的情况。

在保持低开销的同时使跟踪可扩展的关键在于,偶尔分割正在生成的跟踪。每个分割点的行为有点像同时禁用和重新启用跟踪。到目前为止的所有跟踪数据代表一个完整且独立的跟踪,而新的跟踪数据将无缝地从中断处继续。

你可能已经想到,解决这个问题需要反思和重写运行时中跟踪实现的大量基础部分。我们很高兴地说,这项工作在Go 1.22中完成并现已正式推出。重写带来了许多良好的改进,包括对go tool trace命令的一些改进。如果你有兴趣,所有详细内容都在设计文档中。

(注:go tool trace仍会将整个跟踪加载到内存中,但对于由Go 1.22+程序生成的跟踪,移除此限制现已变为可行。)

飞行记录

假设你在开发一个web服务,一个RPC花费了非常长的时间。当你意识到RPC已经运行很久时,你无法在那时开始跟踪,因为导致请求变慢的根本原因已经发生并且没有被记录下来。

有一种称为飞行记录(flight recording)的技术可以帮助解决这个问题,你可能已经在其他编程环境中接触过了。飞行记录的思路是持续开启跟踪,并一直保留最新的跟踪数据,以防万一。然后,一旦发生有趣的事情,程序就可以直接写出它所拥有的数据!

在可以分割跟踪之前,这基本上是行不通的。但由于低开销使得连续跟踪变得可行,而且现在运行时可以随时分割跟踪,因此实现飞行记录变得很直接。

因此,我们很高兴地宣布在golang.org/x/exp/trace包中提供了一个飞行记录器实验。

请尝试使用它!下面是一个设置飞行记录器来捕获长时间HTTP请求的示例,可以帮助你入门。

// 设置飞行记录器
fr := trace.NewFlightRecorder()
fr.Start()
// 设置和运行HTTP服务器
var once sync.Once
http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
    start := time.Now()
    // 干些事情
    doWork(w, r)
    // 盼到了长耗时请求，来个快照
    if time.Since(start) > 300*time.Millisecond {
        // 这里我们为了简化只做一次，实际上你可以做多次
        once.Do(func() {
            // 抓取快照
            var b bytes.Buffer
            _, err = fr.WriteTo(&b)
            if err != nil {
                log.Print(err)
                return
            }
            // 把快照写入文件
            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阻塞事件的比例。

// 开始从标准输入读取跟踪数据。
r, err := trace.NewReader(os.Stdin)
if err != nil {
    log.Fatal(err)
}
var blocked int
var blockedOnNetwork int
for {
    // 读取事件
    ev, err := r.ReadEvent()
    if err == io.EOF {
        break
    } else if err != nil {
        log.Fatal(err)
    }
    // 处理它
    if ev.Kind() == trace.EventStateTransition {
        st := ev.StateTransition()
        if st.Resource.Kind == trace.ResourceGoroutine {
            id := st.Resource.Goroutine()
            from, to := st.GoroutineTransition()
            // 查找阻塞的goroutine, 统计计数
            if from.Executing() && to == trace.GoWaiting {
                blocked++
                if strings.Contains(st.Reason, "network") {
                    blockedOnNetwork++
                }
            }
        }
    }
}
// 打印我们所需
p := 100 * float64(blockedOnNetwork) / float64(blocked)
fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)