Golang Trace
Go语言的trace包是一个用于追踪程序运行时信息的工具,它可以帮助开发者理解程序的运行时行为,诊断性能问题。trace包主要是通过分析程序生成的追踪文件来工作的。
runtime/trace 包含了一个强大的工具,用于理解和排查 Go 程序。它的功能允许我们生成一个时间段内每个 goroutine 的执行轨迹。通过使用 go tool trace 命令(或者优秀的开源工具 gotraceui),我们可以可视化并探索这些轨迹数据。
trace的魔力在于它能轻易揭示程序中那些以其他方式难以发现的事情。例如,一个并发瓶颈,许多 goroutine 在同一个 channel 上阻塞可能在 CPU 分析中很难看出,因为没有执行样本。但在执行trace中,执行链路的缺失将以惊人的清晰度显示出来,被阻塞的 goroutine 的堆栈追踪将迅速指向问题所在。
Go 开发者甚至可以使用任务、区域和日志来为他们的程序添加插桩,这样他们就能将自己的高层次关注点与底层执行细节相关联。
问题
不幸的是,执行trace中的丰富信息往往难以触及。历史上,与trace相关的四个大问题经常成为障碍:
- trace的开销很大。
- trace的扩展性不好,可能变得过于庞大而难以分析。
- 往往不清楚何时开始trace记录以捕获特定的错误行为。
- 鉴于缺乏用于解析和解释执行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)