本卷的第一条纪律是:先让运行时开口说话,再谈优化。运行时是一个黑箱,但它留了五个缺口——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/trace | GoBlock/STWBegin 的分布 |
| goroutine 疑似不被调度 | GODEBUG=schedtrace=1000 | idleprocs、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 |
三条使用纪律,后面每一节都会反复出现:
- 先量再调。 任何优化前先拿到基线数字(
-count≥5的区间),否则无法判断改动是否有效。 - 一次只动一个变量。
GODEBUG键可以叠加,但排查时一次只开一个。 - 实验产物即产即清。
GOSSAFUNC生成的ssa.html、trace.out、mem.out都可能落在当前目录,跑完必须清理,绝不能留在仓库里。
阅读导航:上一节:目录 · 下一节:1.2 源码地图与阅读路线 。
继续阅读
探索更多技术文章
浏览归档,发现更多关于系统设计、工具链和工程实践的内容。