golang

《Go 语言高级编程》6.3 runtime/metrics 与 trace 实战

pprof 回答「哪里慢」，runtime/metrics 回答「现在什么状态」，runtime/trace 回答「时间线长什么样」。本节实测读取 107 个运行时指标、生成并解析 trace 文件，用 go tool trace 的 parsed dump 与 sched pprof 把一次并发执行拆成可读的延迟分布。

Leeting Yan 6 分钟阅读 2840 字

6.3 runtime/metrics 与 trace 实战

卷一 16.2 讲过 pprof 的基础用法——采 CPU、看火焰图。但 pprof 是采样，它回答的是「哪里花了时间」，回答不了「此刻运行时处于什么状态」和「这一秒里 goroutine 的时间线长什么样」。后两个问题分别属于 runtime/metrics 与 runtime/trace。

本节要回答：runtime/metrics 的指标语义是什么，runtime/trace 能记录什么、怎么把它读成可用的结论。结论是：metrics 是「状态快照」，trace 是「时间线录像」；本机实测 go tool trace -pprof=sched 能把一次并发执行拆成 chansend1 327 µs、chanrecv2 324 µs 的延迟分布。

边界说明：卷一 16.2 讲的是「用 pprof 找 CPU/内存热点」；本节讲的是「读运行时状态指标」与「解读 goroutine 时间线」，两者互补而非重叠。

6.3.1 runtime/metrics：稳定的指标接口

runtime/metrics 的设计目标是给监控系统一个稳定的指标名。它不直接暴露 runtime.MemStats 那几十个字段（那些字段会随版本增删），而是用带命名空间的名字 + 统一的 Value 类型。本机实测：

$ GOTOOLCHAIN=go1.27.0 go run ./metrics
total metrics: 107

**Go 1.27 一共暴露 107 个指标。**指标名用斜杠分层，形如 /memory/classes/heap/objects:bytes，末尾的 :bytes、:gc-cycles、:percent 是单位后缀。

读取方式是「先声明要哪些，再一次性 Read」：

names := []string{
	"/memory/classes/heap/objects:bytes",
	"/gc/cycles/total:gc-cycles",
	"/gc/gogc:percent",
	"/gc/gomemlimit:bytes",
	"/sched/gomaxprocs:threads",
	"/sched/latencies:seconds",
}
samples := make([]metrics.Sample, 0, len(names))
for _, n := range names {
	samples = append(samples, metrics.Sample{Name: n})
}
metrics.Read(samples)

Read 是批量、无锁的：它从运行时原子地快照一批值，适合放进指标上报循环。

6.3.2 实测：读到的值

把上面的程序跑起来，真实输出（GOTOOLCHAIN=go1.27.0）：

total metrics: 107
/memory/classes/heap/objects:bytes             = 122752
/memory/classes/heap/free:bytes                = 0
/gc/cycles/total:gc-cycles                     = 0
/gc/gogc:percent                               = 100
/gc/gomemlimit:bytes                           = 9223372036854775807
/sched/gomaxprocs:threads                      = 10
/sched/latencies:seconds                       = histogram(buckets=162)
/cpu/classes/gc/total:cpu-seconds              = 0.000000
/cpu/classes/total:cpu-seconds                 = 0.000000

逐个解读，并对照 6.2 节的调优概念：

指标值含义
/memory/classes/heap/objects:bytes122752堆上活对象字节数（≈ HeapAlloc）
/memory/classes/heap/free:bytes0堆中已归还但未使用的字节
/gc/cycles/total:gc-cycles0累计 GC 次数
/gc/gogc:percent100当前 GOGC（默认 100，与 6.2 一致）
/gc/gomemlimit:bytes9223372036854775807当前内存上限 = math.MaxInt64（即不设）
/sched/gomaxprocs:threads10GOMAXPROCS（本机 10 核可用）
/sched/latencies:secondshistogram(162)goroutine 调度延迟直方图（162 个桶）
/cpu/classes/gc/total:cpu-seconds0.0GC 累计 CPU 秒

两个细节值得强调：

  • gomemlimit:bytes 默认是 math.MaxInt64——这印证了 6.2.3 说的「默认不限」。要监控内存逼近上限，就得看这个值与 heap/objects 的比值。
  • sched/latencies:seconds 是直方图（KindFloat64Histogram），不是标量。它的 162 个桶记录了「goroutine 从就绪到真正被调度」的延迟分布——这是尾延迟调优的核心指标，比平均延迟有用得多。

6.3.3 三种 Value 类型

metrics.Sample.Value 有三种 Kind，代码必须分别处理：

switch s.Value.Kind() {
case metrics.KindUint64:
	fmt.Printf("%s = %d\n", s.Name, s.Value.Uint64())
case metrics.KindFloat64:
	fmt.Printf("%s = %.6f\n", s.Name, s.Value.Float64())
case metrics.KindFloat64Histogram:
	h := s.Value.Float64Histogram()
	fmt.Printf("%s = histogram(buckets=%d)\n", s.Name, len(h.Counts))
default:
	// KindBad：指标名不存在
}

KindBad 是「查了一个不存在的指标名」——不会 panic，只会静默返回坏值。所以上报前应该用 metrics.All() 校验名字：

descs := metrics.All() // 返回全部指标描述（本机 107 个）

All() 返回的是 []metrics.Description，包含每个指标的名字、单位、Kind 与稳定性级别。生产代码里在启动时校验一遍，能挡住「指标名拼错」这类静默故障。

6.3.4 runtime/trace：把时间线录下来

runtime/trace 记录的是事件流：goroutine 何时被创建、何时开始运行、何时阻塞在 channel 或锁上、GC 何时 STW。它比 pprof 重，但能看到 pprof 看不到的东西——因果关系。

最小用法：

f, _ := os.Create("trace.out")
defer f.Close()
trace.Start(f)
// ... 被测代码 ...
trace.Stop()

在代码里还可以打标记，把业务语义嵌进时间线：

ctx, task := trace.NewTask(ctx, "work")
defer task.End()
trace.Logf(ctx, "work", "id=%d sum=%d", id, sum)

本机跑一个 8 goroutine 各做「channel 生产者-消费者 + 短暂 sleep」的程序，生成的 trace 文件：

trace written
-rw-r--r--  44753  trace.out

6.3.5 实测：把 trace 读成结论

go tool trace 有两种用法：起一个 Web UI（go tool trace trace.out），或者用命令行 dump。Web UI 需要浏览器，本机在无头环境下用命令行版本更实际。1.27 的 -d 只接受三种模式（parsed / wire / footprint）：

$ GOTOOLCHAIN=go1.27.0 go tool trace -d=1 trace.out
invalid debug mode 1, want one of: parsed, wire, footprint

$ GOTOOLCHAIN=go1.27.0 go tool trace -d=parsed trace.out | head -8
M=-1 P=-1 G=-1 Sync Time=136222403197248 N=1 Trace=136222403205440 ...
M=8273358976 P=-1 G=-1 StateTransition Time=136222403207744 ProcID=9 Undetermined->Running Reason=""
M=8273358976 P=9 G=-1 StateTransition Time=136222403208000 GoID=1 Undetermined->Running Reason=""
M=8273358976 P=9 G=1 Metric Time=136222403210688 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(10)}

parsed 模式把每条 trace 事件逐行打印，适合 grep 定位；wire 是原始编码；footprint 统计文件占用。更实用的是导出成 pprof 格式再分析：

$ GOTOOLCHAIN=go1.27.0 go tool trace -pprof=sched trace.out > sched.pprof
$ GOTOOLCHAIN=go1.27.0 go tool pprof -top -nodecount=8 sched.pprof
Type: delay
Showing nodes accounting for 776.98us, 78.09% of 994.96us total
      flat  flat%   sum%        cum   cum%
  327.22us 32.89% 32.89%   327.22us 32.89%  runtime.chansend1
  324.25us 32.59% 65.48%   324.25us 32.59%  runtime.chanrecv2
  125.50us 12.61% 78.09%   125.50us 12.61%  sync.(*Mutex).Unlock
         0     0% 78.09%   125.50us 12.61%  fmt.Sprintf
         0     0% 78.09%   125.50us 12.61%  main.work
         0     0% 78.09% 45.29%  main.work
         0     0% 78.09% 32.89%  main.work.func1
         0     0% 78.09% 12.61%  runtime/trace.Logf

这份输出的 Type: delay 是关键：它统计的不是 CPU 时间，而是「阻塞/等待」的时间。读法：

节点延迟含义
runtime.chansend1327.22 µsgoroutine 阻塞在 channel 发送上
runtime.chanrecv2324.25 µs阻塞在 channel 接收上
sync.(*Mutex).Unlock125.50 µs锁竞争
main.workcum 45.29%业务函数的累计延迟占比

这正是 trace 相对 pprof 的价值：pprof 的 CPU profile 里，chansend1 阻塞的时间是「不花 CPU 的」，所以不会出现在 CPU 火焰图上；而 trace 的 sched profile 把它算成 delay，一眼就能看出「瓶颈是 channel 握手，不是计算」。

6.3.6 四种 profile：从 trace 里榨出不同视角

go tool trace -pprof=TYPE 支持四种 TYPE，本机 -help 列得很清楚：

Supported profile types are:
    - net: network blocking profile
    - sync: synchronization blocking profile
    - syscall: syscall blocking profile
    - sched: scheduler latency profile

四种都是 Type: delay——统计的是阻塞时间。对同一个 trace 文件，换 TYPE 就换一个视角。实测 sync（同步阻塞）：

Type: delay
Showing nodes accounting for 3204.82us, 99.93% of 3206.99us total
 2666.94us 83.16% 83.16%  2666.94us 83.16%  sync.(*WaitGroup).Wait
  285.66us  8.91% 92.07%   285.66us  8.91%  runtime.chansend1
  252.21us  7.86% 99.93%   252.21us  7.86%  runtime.chanrecv2

sync.(*WaitGroup).Wait 占 83%——因为主 goroutine 在等 8 个子 goroutine，这是预期内的等待。再看 syscall（系统调用阻塞）：

Type: delay
Showing nodes accounting for 57.92us, 100% of 57.92us total
   57.92us   100%   100%    57.92us   100%  syscall.syscall
         0     0%   100%    57.92us   100%  internal/poll.(*FD).Write

57.92 µs 全部来自一次 os.File.Write（写 trace 文件本身）。四种 profile 的用途对照：

TYPE抓什么阻塞典型用途
sched调度延迟尾延迟、GOMAXPROCS 是否够
sync锁 / channel / WaitGroup并发瓶颈、锁竞争
syscall系统调用磁盘 / 网络 IO 阻塞
net网络读写网络服务延迟

读 profile 的第一原则：区分「预期等待」与「异常等待」。WaitGroup.Wait 占 83% 不一定有问题（主 goroutine 就该等）；真正要看的是它下面挂着的子节点——如果 chansend1 异常高，那才是 channel 成了瓶颈。

6.3.7 trace 的成本与生产使用

trace 是全量事件记录，不是采样，所以成本比 pprof 高。三条使用纪律：

  1. **按需开启，不要常开。**用 HTTP 端点（如 /debug/trace）触发一段有限时长的采集，而不是进程启动就 trace.Start。
  2. 限制时长。go test -trace 或 net/http/pprof 的 ?seconds=N 都能控制窗口；长窗口的 trace 文件会迅速膨胀（本机一个小程序就 44 KB）。
  3. **生产采集要用 runtime/trace 的飞行记录（flight recorder）模式。**它只在内存里保留最近一段窗口，适合「出问题时捞现场」。FlightRecorder 是 Go 1.25 引入的，可用 api 清单核实：
$ grep -h "FlightRecorder" /usr/local/go/api/go1.*.txt | head -3
pkg runtime/trace, func NewFlightRecorder(FlightRecorderConfig) *FlightRecorder #63185
pkg runtime/trace, method (*FlightRecorder) Start() error #63185
pkg runtime/trace, type FlightRecorder struct #63185

// 简化的按需采集：采 3 秒就停
f, _ := os.Create("/tmp/trace.out")
trace.Start(f)
time.Sleep(3 * time.Second)
trace.Stop()
f.Close()

6.3.8 三个工具的分工

工具采样方式回答的问题适用场景
pprof（CPU）采样哪里花 CPU计算热点
runtime/metrics快照此刻什么状态监控上报、告警
runtime/trace全量事件时间线长什么样并发调度、阻塞、尾延迟

选择顺序建议：先用 metrics 建立监控基线，发现异常（如 GC 频率飙升、调度延迟变长）后，用 pprof 找 CPU 热点，用 trace 看时间线因果。

一句话收束：**pprof 看「花在哪」，metrics 看「是什么」，trace 看「怎么发生的」。**三者的成本递增、粒度递减，按问题选工具，而不是每次都上最重的那一个。

阅读导航：上一节：6.2 GC 调优与 GOGC/GOMEMLIMIT · 下一节：7.1 调用开销与栈切换实测 。

继续阅读

探索更多技术文章

浏览归档，发现更多关于系统设计、工具链和工程实践的内容。

全部文章 返回首页

「golang」更多文章

  1. 《Go 语言编程实战》目录
  2. 《Go 语言编程实战》18.3 上线、观测与迭代
  3. 《Go 语言编程实战》18.2 故障演练