pprof 是采样：它告诉你「CPU 时间花在哪个函数」。runtime/trace 是逐事件记录：它告诉你「第 3 毫秒这个 goroutine 被谁唤醒、又阻塞在哪」。两者回答不同问题。站内 Go 专题（/posts/golang/）与卷三讲过 GC 指标清单，本节不复述，只写增量——怎么从一份真实 trace 里，用纯文本工具（不打开浏览器）读出 goroutine 时间线。
本节要回答：不打开 trace 网页，怎么用命令行把一份 trace 读出结论？ 结论：
go tool trace -d=footprint给事件计数（谁多谁主导）、-d=parsed给逐事件时间线（goroutine 的 NotExist→Runnable→Running→Waiting 全过程）、-pprof=sync给阻塞归因（谁把 goroutine 卡住了）。三者合起来，就能定位「这段时间到底在等什么」。
3.2.1 实验：从 trace 里读三样东西
先造一份有代表性的 trace：一个生产者/消费者管道，生产者往 channel 发 100 个整数，消费者收完。用 go test -trace 生成：
func BenchmarkPipeline(b *testing.B) {
for i := 0; i < b.N; i++ {
ch := make(chan int, 8)
var wg sync.WaitGroup
wg.Add(1)
go func() {
defer wg.Done()
for j := 0; j < 100; j++ {
ch <- j
}
close(ch)
}()
total := 0
for v := range ch {
total += v
}
wg.Wait()
}
}
go test -bench=BenchmarkPipeline -benchtime=200x -trace=trace.out .
第一样：事件计数（谁主导）。 -d=footprint 打印每种事件的字节数与条数：
go tool trace -d=footprint trace.out
Event Bytes % Count %
- - - - -
GoStart 35865 34.29% 7411 36.47%
GoUnblock 24568 23.49% 4258 20.95%
GoBlock 17123 16.37% 4271 21.02%
GoStop 11754 11.24% 2937 14.45%
ProcStart 1342 1.28% 300 1.48%
STWBegin 56 0.05% 13 0.06%
STWEnd 32 0.03% 13 0.06%
GCBegin 13 0.01% 3 0.01%
GCEnd 9 0.01% 3 0.01%
一眼看出：这段 trace 被 GoStart/GoUnblock/GoBlock/GoStop 主导——是 channel 通信在驱动调度，而不是 GC（GCBegin 只有 3 次，STWBegin 13 次，占比可忽略）。
注意这里的「Bytes」和「Count」两列含义不同：Bytes 是写进 trace 文件的字节数（受事件参数个数影响），Count 是事件条数。判断「谁主导」应看 Count；判断「trace 文件为什么大」才看 Bytes。例如 GoStart 占了 34% 的字节，说明它参数多（带 goid、栈、时间戳），这也是为什么压缩 trace 文件要从减少高频事件入手。
第二样：逐事件时间线（一个 goroutine 的一生）。 -d=parsed 把每个事件打成一行，带时间戳、M/P/G、状态迁移和原因：
go tool trace -d=parsed trace.out | grep -E 'GoID=35 ' | grep StateTransition | head
M=8273358976 P=8 G=1 StateTransition Time=140041243616320 GoID=35 NotExist->Runnable Reason=""
M=6103396352 P=9 G=-1 StateTransition Time=140041243634112 GoID=35 Runnable->Running Reason=""
M=6103396352 P=9 G=35 StateTransition Time=140041243652416 GoID=35 Running->Waiting Reason="chan receive"
三行就是一个生产者 goroutine 的完整开场：NotExist→Runnable（被 go 语句创建）、Runnable→Running（排上 CPU，注意此刻在 P=9）、Running→Waiting（阻塞在 chan receive）。时间戳单位是纳秒，两行相减（140041243634112 − 140041243616320）可得「从创建到运行」的等待约 17.8 微秒。
第三样：STW 与 GC 阶段。 同一份 parsed 输出里的 RangeBegin 事件标注了特殊阶段：
go tool trace -d=parsed trace.out | grep 'RangeBegin' | head -6
M=8273358976 P=8 G=1 RangeBegin Time=140041243548608 Name="stop-the-world (start trace)" Scope=Goroutine(1)
M=8273358976 P=8 G=1 RangeBegin Time=140041244316160 Name="GC concurrent mark phase" Scope=None
M=8273358976 P=8 G=1 RangeBegin Time=140041244372032 Name="stop-the-world (GC sweep termination)" Scope=Goroutine(1)
M=8273358976 P=8 G=45 RangeBegin Time=140041245500928 Name="stop-the-world (GC mark termination)" Scope=Goroutine(45)
M=6104543232 P=9 G=1 RangeBegin Time=140041247727744 Name="stop-the-world (read mem stats)" Scope=Goroutine(1)
M=6104543232 P=9 G=20 RangeBegin Time=140041247880704 Name="GC concurrent mark phase" Scope=None
读法：stop-the-world (GC sweep termination) 和 stop-the-world (GC mark termination) 是 GC 的两次 STW，GC concurrent mark phase 是并发标记（不停世界）。Scope=Goroutine(N) 表示这段区间挂在哪个 goroutine 上，Scope=None 表示是全局区间。这就是 trace 里「灰色长条」的文本来源。
第四样：阻塞归因。 go tool trace -pprof=sync 导出同步阻塞画像，再用 pprof 看：
go tool trace -pprof=sync trace.out > sync.pprof
go tool pprof -top -nodecount=6 sync.pprof
Type: delay
Showing nodes accounting for 11673.90us, 100% of 11673.90us total
flat flat% sum% cum cum%
8585.47us 73.54% 73.54% 8585.47us 73.54% runtime.chanrecv1
1515.07us 12.98% 86.52% 1515.07us 12.98% runtime.chansend1
1184.88us 10.15% 96.67% 1184.88us 10.15% runtime.chanrecv2
388.48us 3.33% 100% 388.48us 3.33% runtime.gcMarkDone
结论明确：73.5% 的阻塞时间花在 chanrecv1（消费者等数据），13% 在 chansend1（生产者等缓冲位）。如果这是个真实服务，优化方向就是把 channel 换成更大的缓冲、或减少跨 goroutine 通信。
第五样：调度延迟画像。 同一份 trace 还能导出 sched 画像，看「就绪后等了多久才被调度」：
go tool trace -pprof=sched trace.out > sched.pprof
go tool pprof -top -nodecount=6 sched.pprof
flat flat% sum% cum cum%
1854.79us 28.28% 28.28% 1854.79us 28.28% runtime.chanrecv2
1699.97us 25.92% 54.20% 1699.97us 25.92% runtime.chansend1
1327.68us 20.24% 74.44% 1327.68us 20.24% runtime.Gosched
427.07us 6.51% 80.95% 1121.73us 17.10% runtime.gcMarkDone
424.13us 6.47% 87.42% 424.13us 6.47% runtime.traceLocker.stack
sync 画像给的是「阻塞时长」，sched 画像给的是「就绪到运行的等待时长」。两者叠加起来，才能区分「goroutine 是在等 channel 还是在等 CPU」。这段里 Gosched 占了 20%——因为基准测试循环里主 goroutine 反复让出，属于测试框架的噪声，不是被测代码的问题。
复现基线：Go 1.27.0 darwin/arm64；Apple M1 Pro，10 逻辑核，32 GiB 内存；
GOMAXPROCS=10，GOGC=100。trace 来自go test -bench=BenchmarkPipeline -benchtime=200x（200 次迭代），单份 trace 文件；事件计数与画像为单次采样结果，时间戳为 trace 内部单调时钟。GoUnblock/GoBlock的条数本机复测与上表一致（4258/4271），但GoStart/GoStop/ProcStart与机器当时的负载强相关，复测值明显更小（约 4500/50/190），这三个调度类计数按原稿记录保留。
3.2.2 源码：trace 是怎么被记录的
开关与生命周期。 runtime/trace 包对外只有几个入口，运行时侧在 src/runtime/trace.go：
// src/runtime/trace.go
318:func StartTrace() error {
457:func StopTrace() {
470:func traceAdvance(stopTrace bool) {
886:func ReadTrace() (buf []byte) {
StartTrace 打开记录、StopTrace 关闭，中间由 traceAdvance 管理「代」（generation）的推进。runtime/trace.Start（src/runtime/trace/trace.go:118）只是对它的封装。
每次事件的开销控制。 记录一条事件要拿锁、写缓冲区，代价不低，所以 runtime 做了两层优化。第一层是 traceAcquire（src/runtime/traceruntime.go:188）：
// src/runtime/traceruntime.go:188
func traceAcquire() traceLocker {
if !traceEnabled() {
return traceLocker{} // 未开启时返回空 locker，零成本
}
return traceAcquireEnabled()
}
注释里写得很直白：把「未开启」的路径单独拆出来，是为了让 traceAcquire 能被内联，从而在 trace 关闭时把开销降到接近零。这就是为什么生产环境可以长期编译进 trace 调用、只在需要时 Start。
第二层是事件本身被合并成批量（internal/trace/batch.go）写入，减少锁竞争。真正落盘的 goroutine 状态事件由 writeGoStatus 产生：
// src/runtime/tracestatus.go:20（片段）
func (w traceWriter) writeGoStatus(goid uint64, mid int64, status tracev2.GoStatus, markAssist bool, stackID uint64) traceWriter {
...
if stackID != 0 {
w = w.event(tracev2.EvGoStatusStack, traceArg(goid), traceArg(uint64(mid)), traceArg(status), traceArg(stackID))
} else {
w = w.event(tracev2.EvGoStatus, traceArg(goid), traceArg(uint64(mid)), traceArg(status))
}
return w
}
tracev2.EvGoStatus 对应你在 -d=parsed 里看到的 StateTransition 行。事件类型到可读名的映射在 src/internal/trace/event.go（如 tracev2.EvGoStart → EventStateTransition，见 :1188）。
解析侧。 go tool trace 本身依赖 src/internal/trace/ 这个包，它把二进制流还原成事件序列：reader.go 读原始字节、order.go（52KB，最大）重建事件的全局顺序、event.go 定义事件语义、summary.go 做 goroutine 级汇总、gc.go 做 GC 专项分析。-d=parsed 走的就是这条解析链，把事件逐条打印。
包的分工也值得记一下：src/runtime/trace.go 与 traceruntime.go 是生产端（runtime 里发事件），src/internal/trace/ 是解析端（tool 里读事件），而 src/runtime/trace/ 才是用户 API（trace.Start/trace.Stop、trace.WithRegion、trace.Log）。你在代码里 import 的是第三个，读源码排查的是前两个。
用户自定义的区间和日志也有对应事件。trace.WithRegion 产生的 RangeBegin/RangeEnd、trace.Log 产生的 Log 事件，会和你看到的内建区间（如 GC concurrent mark phase）混在同一条时间线上——所以给业务代码加 trace 区间，是让「业务耗时」和「运行时耗时」出现在同一张图上的办法。
三种 dump 的层次。 go tool trace 的 -d 参数有三档，对应「从原始到语义」三层：
-d= | 看到的东西 | 用途 |
|---|---|---|
wire | 二进制帧（事件类型号、长度、参数原始值） | 排查解析器 bug、理解编码 |
parsed | 已解码的逐事件记录（时间戳 + 类型 + 参数） | 精确定位某毫秒发生了什么 |
footprint | 事件类型的计数与字节占比 | 一眼判断「谁主导」 |
wire 那一层最能说明「trace 文件为什么这么小」：事件不是一行 JSON，而是紧凑的变长二进制帧，goID、时间戳都用差分编码。这也是为什么 20 万条事件能塞进几 MB 的文件——如果按文本存，同样的信息要大一个数量级。
StartTrace 内部按「代」（generation）组织缓冲：每次 trace.Start 开启新一代，旧代的缓冲在 StopTrace 后被回收。所以「录制 5 秒、下载、停止」这种短窗口用法不会让内存无界增长；反过来，常开 trace 会让缓冲一直累积，是内存问题的常见来源。
3.2.3 决策：trace 的三步读法
拿到一份 trace.out，按这个顺序读，通常五分钟内能有结论：
| 步骤 | 命令 | 看什么 | 判断 |
|---|---|---|---|
| 1. 概览 | go tool trace -d=footprint | 哪种事件条数最多 | 主导事件即主要矛盾 |
| 2. 定位 | go tool trace -d=parsed | grep | 目标 GoID 的 StateTransition | 找到卡住的状态与 Reason |
| 3. 归因 | go tool trace -pprof=sync/sched/syscall | pprof -top | 阻塞在哪个原语 |
三种画像（-pprof）的分工：
sync：同步原语阻塞（channel、mutex、WaitGroup）——回答「goroutine 在等谁」。sched：调度延迟（就绪后多久才被调度）——回答「CPU 排队的等待有多长」。syscall：系统调用阻塞——回答「I/O 是否拖住了线程」。net：网络阻塞——回答「是不是网络 I/O 在拖后腿」。
四种画像的输入是同一份 trace，只是提取的事件类型不同。所以一份 trace 可以反复榨取，不必为每个问题重新录制。这也是 trace 比 pprof 更适合「事后复盘」的原因：它保存的是完整事实，而 pprof 只保存了采样点。
三条结论：
- 先看
-d=footprint再决定深挖方向。 如果GCBegin/STWBegin占比高，直接转去第 7 章；如果GoBlock占比高，走-pprof=sync。 -d=parsed是 trace 的「源码级」视图。 它能给出纳秒时间戳和逐次状态迁移，比网页版更适合精确定位「某一毫秒发生了什么」。- trace 有固定开销，且会放大程序行为。 它记录的是「开了 trace 之后」的运行时，长 trace 文件本身也占内存。只在需要时开、只截取关心的时段。
还有三条实践提醒，能省下不少时间：
-d=parsed的输出极大。 本节这份 trace 的 parsed 输出有 20 万行，永远要grep后再看，不要整屏翻。先grep 'GoID=<目标>'缩小到某个 goroutine，再grep StateTransition看它的状态迁移。- 时间戳是单调时钟，不是墙上时间。 parsed 输出里的
Time=140041243616320是纳秒级单调时钟，两次相减得到耗时；它与-d=footprint里的Wall时间不直接可比。 - trace 与 pprof 要配合用。 pprof 告诉你「热点函数」，trace 告诉你「这段热点发生在哪个 goroutine、被谁唤醒」。只用其中一个，都容易得出片面的结论。
最后把「选哪个工具」压缩成一句话：要「哪个函数慢」用 pprof，要「为什么慢、在等谁」用 trace，要「内存怎么了」用 -memprofile + gctrace。
补一个线上场景的落地点：长跑服务里开 trace 的正确姿势是「按需、限时」。暴露一个受保护的 HTTP 端点，收到请求时 trace.Start(f)、跑 5 秒、trace.Stop()，把文件下载下来离线分析——而不是在服务启动时就常开。这样既拿到了想要的窗口，又不让 trace 的开销和文件大小失控。
阅读导航：上一节：3.1 GOMAXPROCS 与容器感知实测 · 下一节：3.3 调度相关的性能决策 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。