《Go 语言运行时原理》1.1 实验驱动方法:GODEBUG、pprof、trace 与 SSA dump

运行时看不见就调不动。本节把 GODEBUG(gctrace/inittrace/schedtrace)、pprof、runtime/trace、-gcflags 与 GOSSAFUNC 五类观测工具各真跑一遍,贴出本机终端回显,定位到 src/runtime/runtime1.go:parsedebugvars 等源码位置,最后给出一张「症状→工具」决策表。

本卷的第一条纪律是:先让运行时开口说话,再谈优化。运行时是一个黑箱,但它留了五个缺口——GODEBUG 环境变量、runtime/pprof、runtime/trace、-gcflags 编译标志、以及 GOSSAFUNC。这一节不是概念介绍,而是把这五个缺口逐个打开,贴出本机真实回显,并指出每个开关在源码里的读取位置。后面的每一节都会复用这套方法。

本节要回答:面对一个运行时的疑问(延迟、内存、CPU),该先拉哪个开关? 结论是:内存与 GC 用 GODEBUG=gctrace=1,调度用 GODEBUG=schedtrace=1,耗时归因用 pprof,时间线归因用 runtime/trace,而「编译器到底做了什么」用 -gcflags=-m 与 GOSSAFUNC。五者不是替代关系,是分层关系。

1.1.1 实验:五类观测工具各跑一遍

先给一个能同时触发分配、GC 与并发的探针程序,后面的实验都用它:

package main

import (
	"fmt"
	"runtime"
	"sync"
)

type point struct{ x, y float64 }

func alloc() {
	s := make([]*point, 0, 1024)
	for i := 0; i < 1024; i++ {
		s = append(s, &point{float64(i), float64(i) * 2})
	}
	runtime.KeepAlive(s)
}

func work(n int) {
	var wg sync.WaitGroup
	for i := 0; i < n; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			alloc()
		}()
	}
	wg.Wait()
}

func main() {
	fmt.Println("GOMAXPROCS =", runtime.GOMAXPROCS(0), "NumCPU =", runtime.NumCPU())
	for i := 0; i < 200; i++ {
		work(4)
	}
	fmt.Println("done")
}

第一类:GC 追踪。 GODEBUG=gctrace=1 每轮 GC 打印一行,是排查内存问题最廉价的手段:

GODEBUG=gctrace=1 ./demo 2>&1 | head -6
GOMAXPROCS = 10 NumCPU = 10
gc 1 @0.004s 1%: 0.028+0.59+0.021 ms clock, 0.28+0/0.64/0+0.21 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 2 @0.008s 1%: 0.065+0.48+0.004 ms clock, 0.65+0.12/0.002/0+0.043 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 3 @0.014s 1%: 0.060+0.55+0.022 ms clock, 0.60+0.034/0.11/0+0.22 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
done

第二类:初始化追踪。 GODEBUG=inittrace=1 打印每个包的 init() 耗时与分配量,用来找「启动慢」的元凶:

GODEBUG=inittrace=1 ./demo 2>&1 | head -14
init internal/bytealg @0 ms, 0 ms clock, 0 bytes, 0 allocs
init internal/runtime/sys @0.014 ms, 0 ms clock, 0 bytes, 0 allocs
init runtime @0.020 ms, 0.085 ms clock, 0 bytes, 0 allocs
init errors @0.41 ms, 0 ms clock, 0 bytes, 0 allocs
init iter @0.46 ms, 0.001 ms clock, 16 bytes, 1 allocs
init sync @0.47 ms, 0 ms clock, 0 bytes, 0 allocs
init syscall @0.48 ms, 0.071 ms clock, 1240 bytes, 7 allocs
init time @0.56 ms, 0.014 ms clock, 0 bytes, 0 allocs
init io/fs @0.59 ms, 0 ms clock, 0 bytes, 0 allocs
init os @0.60 ms, 0.11 ms clock, 7712 bytes, 22 allocs
init unicode @0.73 ms, 0.001 ms clock, 512 bytes, 4 allocs
init reflect @0.74 ms, 0 ms clock, 0 bytes, 0 allocs
GOMAXPROCS = 10 NumCPU = 10
done

第三类:调度器追踪。 GODEBUG=schedtrace=1000 每秒打印一行全局调度状态;探针跑得太快只有一行,所以换成 24 个 CPU 密集型 goroutine、持续 2.5 秒的程序:

GODEBUG=schedtrace=800 ./sched
SCHED 0ms: gomaxprocs=10 idleprocs=8 threads=3 spinningthreads=1 needspinning=0 idlethreads=0 runqueue=0 [ 0 0 0 0 0 0 0 0 0 0 ] schedticks=[ 0 0 0 0 0 0 0 0 0 0 ]
SCHED 811ms: gomaxprocs=10 idleprocs=0 threads=11 spinningthreads=0 needspinning=1 idlethreads=0 runqueue=8 [ 1 0 1 0 1 1 1 0 0 1 ] schedticks=[ 34 30 31 29 31 31 31 31 33 34 ]
SCHED 1624ms: gomaxprocs=10 idleprocs=0 threads=11 spinningthreads=0 needspinning=1 idlethreads=0 runqueue=8 [ 1 1 0 1 0 0 1 1 1 0 ] schedticks=[ 65 62 62 61 61 63 63 63 65 65 ]
SCHED 2427ms: gomaxprocs=10 idleprocs=0 threads=11 spinningthreads=0 needspinning=1 idlethreads=0 runqueue=8 [ 1 1 0 0 0 1 0 1 1 1 ] schedticks=[ 86 83 84 82 82 84 84 84 86 86 ]

方括号里是每个 P 的本地运行队列长度,runqueue=8 是全局队列。24 个 goroutine 对 10 个 P,idleprocs=0 说明没有空转的 P——这正是 work stealing 生效的样子。

第四类:pprof。 内存热点用 -memprofile,然后 -top 看排序、-list 看行级归因:

go test -bench=BenchmarkAlloc -benchmem -count=5 -memprofile=mem.out .
go tool pprof -list=BenchmarkAlloc mem.out
Total: 21.58GB
ROUTINE ======================== benchdemo.BenchmarkAlloc in /tmp/gbrt1/bench/bench_test.go
   21.58GB    21.58GB (flat, cum)   100% of Total
         .          .      9:func BenchmarkAlloc(b *testing.B) {
         .          .     10:	for i := 0; i < b.N; i++ {
    7.19GB     7.19GB     11:		s := make([]*point, 0, 64)
         .          .     12:		for j := 0; j < 64; j++ {
   14.39GB    14.39GB     13:			s = append(s, &point{float64(j), 1})
         .          .     14:		}

第五类:runtime/trace。 它不是采样,是逐事件记录,回答的是「这段时间到底发生了什么」:

go test -bench=BenchmarkPipeline -benchtime=200x -trace=trace.out .
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%

GoStart/GoStop 是 goroutine 的调度进出,STWBegin/STWEnd 成对出现,GCBegin/GCEnd 只有 3 次——一眼就能判断这段时间被谁主导。

编译器侧两个开关。 -gcflags=-m 输出内联与逃逸决策:

go build -gcflags='-m' .
# ssademo
./main.go:10:6: can inline sumSlice
./main.go:19:33: inlining call to sumSlice
./main.go:19:13: inlining call to fmt.Println
./main.go:10:15: s does not escape
./main.go:19:17: add(2, 3) escapes to heap
./main.go:19:33: ~r0 escapes to heap
./main.go:19:39: []int{...} does not escape

GOSSAFUNC=<函数> 会生成 ssa.html,里面是逐 pass 的 SSA 快照。用一个只有两个函数的程序跑出来,pass 列有 17 个:

GOSSAFUNC=sumSlice go build .
python3 -c "import re;print(re.findall(r'id=\"([\w\-]+)-col\"',open('ssa.html').read()))"
['sources', 'AST', 'before-insert-phis', 'start', 'number-lines', 'early-phielim-and-copyelim', 'early-deadcode', 'short-circuit', 'opt', 'zero-arg-cse', 'divisible', 'decompose-builtin', 'generic-deadcode', 'late-fuse', 'loop-rotate', 'trim', 'genssa']

复现基线:Go 1.27.0 darwin/arm64;Apple M1 Pro(8 性能核 + 2 能效核,共 10 逻辑核),32 GiB 内存;GOMAXPROCS=10,GOGC/GOMEMLIMIT 未设置(默认)。基准重复 -count=5。ssa.html 在实验后已删除,未留在仓库目录。trace 的 GoUnblock/GoBlock 计数本机复测与上表一致(4258/4271),但 GoStart/GoStop/ProcStart 与机器当时的负载强相关,复测值明显更小(约 4500/50/190),这三个调度类计数按原稿记录保留。

1.1.2 源码:这些开关在哪里被读取

所有 GODEBUG 键在启动时由一张表统一解析。表在 src/runtime/runtime1.go:

// src/runtime/runtime1.go:304(debug 结构体片段)与 :357(dbgvars 表片段)
var debug struct {
	...
	gctrace                  int32
	schedtrace               int32
	asyncpreemptoff          int32
	inittrace       int32
}
var dbgvars = []*dbgVar{
	{name: "asyncpreemptoff", value: &debug.asyncpreemptoff},
	{name: "gctrace", value: &debug.gctrace},
	{name: "inittrace", value: &debug.inittrace},
	{name: "schedtrace", value: &debug.schedtrace},
}

parsedebugvars(同文件)遍历这张表,把环境变量写进 debug.* 字段。所以「有哪些 GODEBUG 键」的权威答案就是这张 dbgvars 表,而不是文档。

三个打印点的位置也很明确:gctrace 每行由 src/runtime/mgc.go:1588 的 if debug.gctrace > 0 { ... print("gc ", ...) } 输出;schedtrace 的主体是 src/runtime/proc.go:6950 的 func schedtrace(detailed bool),由 proc.go:6664 在 sysmon 里按周期调用;inittrace 由 src/runtime/proc.go:202 的 if debug.inittrace != 0 分支打印。

编译器的 GOSSAFUNC 只有一行读取代码,在 src/cmd/compile/internal/ssagen/ssa.go:65:

// src/cmd/compile/internal/ssagen/ssa.go:65
var (
	ssaDump = os.Getenv("GOSSAFUNC")
)

当 ssaDump 匹配到正在编译的函数名时,编译器就会把每个 pass 的 SSA 写进 ssa.html(src/cmd/compile/internal/ssa/html.go)。这就是为什么 GOSSAFUNC 必须在 build 阶段设置,而不是运行阶段——它影响的是编译输出,不是程序行为。

1.1.3 决策:症状 → 工具

把上面的实验整理成一张可以直接照做的表:

你观察到的症状第一个该拉的开关看什么
内存曲线锯齿、GC 频繁GODEBUG=gctrace=1每轮 GC 的 ms clock、堆目标 MB goal
CPU 占用高但吞吐不涨pprof(CPU profile)-top 里的 flat 排序
延迟毛刺、找不到热点runtime/traceGoBlock/STWBegin 的分布
goroutine 疑似不被调度GODEBUG=schedtrace=1000idleprocs、runqueue、每 P 队列长度
启动慢GODEBUG=inittrace=1哪个包的 init 耗时/分配大
怀疑某变量逃逸-gcflags='-m'escapes to heap 行
想看某个优化是否生效GOSSAFUNC=<fn> + -d=ssa/<pass>/debug=1对应 pass 前后的 SSA
想知道循环边界检查能否消除-gcflags='-d=ssa/check_bce/debug=1'有无 Found IsInBounds

三条使用纪律,后面每一节都会反复出现:

  1. 先量再调。 任何优化前先拿到基线数字(-count≥5 的区间),否则无法判断改动是否有效。
  2. 一次只动一个变量。 GODEBUG 键可以叠加,但排查时一次只开一个。
  3. 实验产物即产即清。 GOSSAFUNC 生成的 ssa.html、trace.out、mem.out 都可能落在当前目录,跑完必须清理,绝不能留在仓库里。

阅读导航:上一节:目录 · 下一节:1.2 源码地图与阅读路线 。

继续阅读

探索更多技术文章

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

全部文章 返回首页

「golang」更多文章

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