Go trace scheduler 延迟和 CPU profile 如何配合

Go 服务出现“请求偶尔变慢”时，单看 CPU profile 很容易漏掉排队：一个 goroutine 可能根本没有拿到处理器，自然不会出现在 CPU 热点里。更稳妥的配合方式是让 runtime/trace 和 runtime/pprof.StartCPUProfile 覆盖同一段负载，用 trace 的 scheduler latency 先回答“可运行的 goroutine 等了多久”，再用 CPU profile 回答“真正运行时把时间花在哪”。

先把两种“慢”分开

go tool trace -pprof=sched 生成的 scheduler latency profile，核心是 goroutine 进入 runnable 状态后，到实际开始执行之间的时间。它适合观察处理器供给不足、可运行队列堆积或唤醒后迟迟得不到执行的场景；一个 goroutine 如果一直阻塞在 channel 或 mutex 上，还没有重新变成 runnable，就不能用这个画像解释它的全部等待。

CPU profile 的语义不同：它按采样点统计正在使用 CPU 的调用栈。某个函数在 CPU profile 中样本很多，说明它在运行时占用了处理器时间；样本很少不能证明请求不慢，可能只是请求时间耗在调度排队、网络、系统调用或同步等待上。

同一负载里同时留下两份证据

不要先采 trace、再换一套请求去采 CPU profile。负载、数据规模和并发度变化后，两个画像无法直接对齐。下面的最小示例把采集窗口放在同一个 runWorkload 调用内；示例中的业务函数只是占位，替换成你的复现路径即可。

package main

import (
    "os"
    "runtime/pprof"
    "runtime/trace"
)

func main() {
    traceFile, err := os.Create("trace.out")
    if err != nil {
        panic(err)
    }
    // trace 记录调度、GC、系统调用等事件，关闭文件确保内容落盘。
    if err := trace.Start(traceFile); err != nil {
        panic(err)
    }

    cpuFile, err := os.Create("cpu.pprof")
    if err != nil {
        trace.Stop()
        _ = traceFile.Close()
        panic(err)
    }
    // CPU profile 与 trace 覆盖同一段负载，便于按时间窗口对照。
    if err := pprof.StartCPUProfile(cpuFile); err != nil {
        trace.Stop()
        _ = traceFile.Close()
        _ = cpuFile.Close()
        panic(err)
    }

    runWorkload()

    // 先停止 CPU 采样，再停止 trace，避免把收尾动作混进业务窗口。
    pprof.StopCPUProfile()
    _ = cpuFile.Close()
    trace.Stop()
    _ = traceFile.Close()
}

func runWorkload() {
    // 替换成能稳定复现延迟的请求、基准或离线任务。
}

如果问题来自测试或基准，也可以直接使用 go test -trace=trace.out 生成 trace；CPU profile 则可用测试的 -cpuprofile 选项采集。关键不是命令长短，而是两份数据必须覆盖相同的工作量和异常窗口。

从 trace 导出 scheduler latency，再用 pprof 看栈

trace 文件可以直接打开查看时间线，也可以导出 pprof 兼容的 scheduler 画像。导出后先看累计栈，再回到 trace 查看对应 goroutine 的上下文：

# 从同一次 trace 中导出调度延迟画像
go tool trace -pprof=sched trace.out > sched.pprof

# 先看累计样本，定位哪些调用路径下的 goroutine 在排队
go tool pprof -top -cum sched.pprof

# 需要图形化调用关系时输出 SVG，避免把单个函数误当成根因
go tool pprof -svg sched.pprof > sched.svg

这里的栈更像“谁创建或唤醒了这批 runnable 工作”的线索，不是“谁消耗了这些等待时间”。例如调度延迟栈集中在请求分发路径，且并发 goroutine 很多，优先检查 GOMAXPROCS、突发并发和长时间 CPU 临界区；如果栈显示大量短任务频繁唤醒，则要检查 goroutine 数量、channel 往返和批量化机会。

用 CPU profile 给排队线索定性

再看同一窗口的 CPU profile：

# 查看直接消耗 CPU 的函数和包含子调用的累计占比
go tool pprof -top cpu.pprof
go tool pprof -top -cum cpu.pprof

flat 高，通常说明函数本身是计算热点；cum 高但 flat 低，说明耗时主要在它调用的下层。把这份结果和 scheduler profile 放在一起，常见判断可以压缩成下面四种：

这张表是缩小范围的工具，不是自动根因判定。尤其要注意 profile 会互相影响：Go 官方诊断文档明确提醒，某些精确内存或阻塞画像可能改变 CPU profile 或 scheduler trace 的表现，因此一次只开启当前问题需要的采集项。

复采时只比较可比的窗口

修复后不要只看一次 profile 的百分比变化。固定请求数量或基准迭代次数，保持数据规模、实例规格和 GOMAXPROCS 不变，并记录采集时长。若降低了并发，scheduler 延迟下降但吞吐也下降，这只能说明排队变少，不能直接宣布优化成功。

更可靠的结果是：相同工作量下，p99 延迟、scheduler 等待分布和 CPU 热点同时朝预期方向移动。例如把计算批量化后，业务热点累计样本下降且吞吐不降；减少无效 goroutine 后，scheduler 等待下降而 CPU 中的调度开销也不再占据显著比例。

相关问题

scheduler profile 能直接找出慢函数吗？

不能。它定位的是 runnable goroutine 的调度等待，慢函数要结合 CPU profile 的 flat/cum 样本判断。

CPU profile 很低就代表服务没有 CPU 问题吗？

不代表。请求可能大部分时间在等待网络、锁、channel 或调度；应回到 trace 看阻塞和 runnable 状态。

为什么两份 profile 的时间不能直接相加？

它们统计的对象不同：一个统计调度等待，一个采样主动运行的栈。应对齐同一负载窗口，用于交叉解释，而不是相加成总耗时。