读懂 runtime/trace：调度延迟、GC 与 Goroutine 阻塞

CPU profile 告诉你“采样时 CPU 正在执行什么”，执行 trace 则记录 goroutine 状态转换、调度、系统调用、网络等待和 GC 事件。它适合回答：为什么明明 CPU 不满，请求仍在排队？

Trace 看的是时间线

    gantt
    title 一次请求可能经历的状态
    dateFormat X
    axisFormat %Lms
    section Goroutine
    可运行但未获调度 :0, 20
    执行业务代码       :20, 35
    网络等待           :35, 80
    再次可运行         :80, 95
    执行并完成         :95, 110
    section Runtime
    GC STW             :45, 48
  

“业务代码只跑了 30ms”与“请求耗时 110ms”并不矛盾。剩下的时间可能在 runnable 队列、channel、mutex、网络轮询器、系统调用或 GC assist 中。

三种采集方式

测试最简单：

go test -run TestCheckout -trace=trace.out ./internal/checkout
go tool trace trace.out

程序内采集适合可控复现：

f, err := os.Create("trace.out")
if err != nil { return err }
defer f.Close()

if err := trace.Start(f); err != nil { return err }
defer trace.Stop()

runWorkload()

运行中的服务可以通过 net/http/pprof 的 trace 端点抓短窗口：

curl -o trace.out 'http://127.0.0.1:6060/debug/pprof/trace?seconds=5'
go tool trace trace.out

Trace 事件量大且有开销，窗口应尽量短并覆盖症状。先用指标确定尖峰时间，再抓取；长时间盲录既扩大文件，也让关键区间难以阅读。管理端点同样必须限制访问。

阅读时先问三个问题

1. Goroutine 是 Running、Runnable 还是 Waiting？

• Running：正在某个线程上执行。
• Runnable：已经可以运行，却还没获得处理器；持续时间长可能是 CPU 饱和、GOMAXPROCS 受限或大量 runnable goroutine 争抢。
• Waiting：在 channel、mutex、网络、timer 或系统调用等待；原因需结合事件和栈。

不要把 Waiting 一概视为问题。服务的大量连接 goroutine 等网络是正常的，关键是它是否阻碍请求目标、等待是否有上限。

2. 延迟发生在业务区域还是运行时事件？

用 task 和 region 给 trace 增加业务语义：

func checkout(ctx context.Context, orderID string) error {
	ctx, task := trace.NewTask(ctx, "checkout")
	defer task.End()
	trace.Log(ctx, "order_id", orderID)

	var err error
	trace.WithRegion(ctx, "reserve-inventory", func() {
		err = reserve(ctx, orderID)
	})
	return err
}

Task 可以跨 goroutine 传播同一个 Context，Region 标记一段工作，Log 添加低量级事件。标签应克制；把每个循环迭代都记录下来会淹没真正结构。

    flowchart LR
    T["Task: checkout"] --> R1["Region: reserve inventory"]
    T --> R2["Region: charge payment"]
    T --> R3["Region: persist order"]
    R1 --> G1["goroutine / RPC"]
    R2 --> G2["goroutine / RPC"]
  

3. GC 是原因，还是恰好同时发生？

Trace 会展示 GC 周期、Stop-the-world 和 goroutine 的 GC assist。短暂 STW 附近有延迟，不代表 GC 就是主因。应同时看：分配速率、堆增长、assist 时间、CPU profile 和 runtime 指标。若请求 goroutine 大量做 assist，通常先降低热点分配，再考虑调 GC 参数。

一个调度延迟排查例子

假设 p99 间歇升高，CPU 只有 70%。Trace 中发现：每次批任务到达会瞬间创建数万 goroutine，Runnable 队列变长，在线请求要等几十毫秒才能运行。此时 CPU 平均值掩盖了短窗口饱和。

修复不是“增大超时”，而是限制批任务并发、建立背压，并把在线与离线工作隔离。再次采集 trace，应看到 runnable 延迟收缩；再用负载测试确认 p99，而不是凭图形变好就结束。

Trace 与其他工具的分工

    flowchart TD
    A["性能异常"] --> B{"主要资源已知吗？"}
    B -->|CPU / 内存 / 锁| P["pprof 定位热点"]
    B -->|调度 / 时序 / 因果不清| T["runtime/trace"]
    T --> H["形成假设"]
    P --> H
    H --> M["Benchmark 或负载测试验证"]
  

Trace 不是日常监控格式，也不是 pprof 的替代品。它提供更完整的执行时间线，代价是数据更重、阅读更复杂。把它用在“采样 profile 解释不了的时间去哪了”，价值最大。

进一步阅读：runtime/trace、More powerful Go execution traces、Go Diagnostics。