1

更强大的Go执行跟踪能力

 1 month ago
source link: https://colobu.com/2024/03/18/execution-traces-2024/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

更强大的Go执行跟踪能力

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

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

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

gotooltrace.png

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
// 读取事件
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)

就像飞行记录器一样,有一个提案问题可以作为留下反馈的好地方!

我们想特别提及Dominik Honnef,他很早就试用了这个API,提供了宝贵的反馈,并为API贡献了对旧版本跟踪的支持。

这项工作能够完成,在很大程度上要感谢一年多前成立的诊断工作组的帮助,该小组由来自Go社区各界的利益相关者组成,并向公众开放。

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

你们所做的讨论、反馈和工作是我们走到今天这一步的关键推动力。再次感谢!


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK