Go runtime/trace 如何观察一次请求的调度过程

接口偶发变慢时，日志只能告诉你“请求花了多久”，却不一定能说明这段时间是在等待 channel、锁、网络系统调用，还是被 GC 和调度切开。Go 的 runtime/trace 适合抓取一个短窗口：用 trace.Start 开始、trace.Stop 收尾，再用任务和区域标记把一次请求和业务阶段关联起来。

最稳妥的做法是只采集一次可控请求或一小段低并发复现，把 trace 保存为文件后用 go tool trace trace.out 阅读；它擅长解释 goroutine 在什么时候运行、等待和被系统调用打断，不是 CPU 热点或内存泄漏的替代品。

先划定一次请求的 trace 窗口

execution trace 会记录 goroutine 创建、阻塞和唤醒、系统调用、GC、堆大小变化以及处理器状态等事件。信息很丰富，也意味着文件和分析成本会随着采集时间增长。runtime/trace.Start 只能在当前程序没有启用 tracing 时开始，Stop 返回前会等待 trace 写完，所以不要把它当成常驻开关随手打开。

下面的骨架适合放在一次本地复现或受保护的诊断入口周围。真正的请求调用放在 handleOneRequest 位置；示例只表达采集边界，不把未执行的输出当成运行证据。

f, err := os.Create("trace.out")
if err != nil {
    log.Fatal(err)
}
defer func() {
    // 关闭文件，确保 trace 文件句柄被释放。
    if err := f.Close(); err != nil {
        log.Fatal(err)
    }
}()

if err := trace.Start(f); err != nil {
    // 已有 tracing 时不要重复 Start，先结束上一采集窗口。
    log.Fatal(err)
}
defer trace.Stop()

// 只把目标请求或短时复现放进采集窗口。
handleOneRequest(ctx)

并发服务里，Start 采集的是进程中同时发生的事件，而不是“只属于某个 HTTP 请求”的天然过滤器。因此诊断时要降低并发、缩短窗口，并用 task 或日志字段确认哪一段事件属于目标请求。

用 task 和 region 标记请求链路

只看时间线很容易迷路。trace.NewTask 为一次逻辑操作建立上下文，派生 goroutine 可以继续携带它；trace.StartRegion 则适合标记当前 goroutine 内的阶段，例如读取请求、等待下游和组装响应。区域必须在启动它的 goroutine 中结束，最小写法通常是 defer。

func handleOneRequest(parent context.Context) {
    ctx, task := trace.NewTask(parent, "http-request")
    defer task.End()

    // 区域覆盖同一 goroutine 内的可辨识业务阶段。
    trace.WithRegion(ctx, "load-data", func() {
        loadData(ctx)
    })

    go func() {
        // 派生 goroutine 继续使用 ctx，便于和请求任务关联。
        trace.WithRegion(ctx, "prepare-response", prepareResponse)
    }()
}

标记名称要少而稳定，例如固定使用 load-data，不要把用户 ID、订单号这类高基数字段拼进 region 名称。需要附加低频线索时可以使用 trace.Log；它适合表达分类和短消息，不适合代替业务日志。

用 go tool trace 找调度证据

采集完成后先在本地打开 trace：

# 用 Go 自带工具读取短时执行轨迹。
go tool trace trace.out

阅读时按“请求任务 → goroutine 状态 → runtime 事件”的顺序收敛问题：目标任务是否长时间没有运行？等待点是 channel、同步原语还是网络系统调用？同一时间是否出现 GC 或并行度下降？如果用户标记只覆盖了 handler，却没有覆盖派生 goroutine，就不要把未标记的空白时间直接归因于某个业务阶段。

把 trace 现象对应到工程动作

如果 trace 暴露的是等待链，先减少共享锁竞争、拆分过长的同步阶段或检查下游超时；如果它显示计算密集但并行度不足，再回到 worker 数量和任务拆分。若目标是找“哪个函数消耗 CPU”，应改用 CPU profile；若目标是解释堆对象为何持续增长，则需要 heap profile。trace 给出的是调度和延迟上下文，不能单独完成所有性能归因。

上线前可按这份清单复查：

• 是否只在受保护的诊断路径开启短窗口，而不是让所有请求长期 tracing？
• 是否在 trace.Start 失败时处理重复采集，并确保 trace.Stop 一定执行？
• 是否给请求任务、关键阶段和派生 goroutine 使用稳定、低基数的标记？
• 是否把 trace 观察到的线索交给 pprof、指标和日志做第二证据？

相关问题

为什么 trace 文件打开后看不到目标请求？

常见原因是采集窗口没有覆盖请求，或者目标请求在另一个进程中。把 Start 提前、Stop 延后一点，并确认客户端和服务端的进程边界。

runtime/trace 能替代 pprof 吗？

不能。trace 更适合看调度、阻塞、GC 和系统调用的时间关系；CPU、内存和锁热点仍应使用对应的 profile。

可以同时调用两次 trace.Start 吗？

不可以。Start 在 tracing 已启用时返回错误；把采集窗口集中到一次复现，并让 Stop 在所有写入完成后收尾。