7.2 GC trace 与延迟分析
7.1 给出的是「参数怎么影响指标」的矩阵，这一节往下钻一层：GODEBUG=gctrace=1 那一行到底在说什么，以及怎么从一行行数字里定位延迟的真正来源。
本节要回答的问题是：
gctrace每一列来自哪里、尾延迟的毛刺是不是 GC 造成的？ 结论是：gctrace的goal列就是存活堆 × (1 + GOGC/100)，而尾延迟的主导项往往不是 STW 暂停（实测普遍在 10–40 微秒），而是辅助标记（mark assist）与调度延迟。本节的增量是 pacing 算法与延迟分析；runtime/metrics的指标清单与语义属于卷三《Go 语言高级编程》6.3，GOGC取值建议属于卷三 6.2，本节都不重复，只讲怎么用它们定位问题。
7.2.1 实验：从 gctrace 到延迟直方图
复现基线
- Go 版本：
go version go1.27.0 darwin/arm64（GOTOOLCHAIN=go1.27.0） - 机器：Apple M1 Pro，10 核，32 GiB 内存
GOMAXPROCS：默认 10；未开-race- 负载：
gctrace用 7.1 的gcmatrix（n=5000000）；延迟直方图用一个 20 万次请求、每次分配 2 KB 的处理器，每种GOGC重复 5 次取区间
先看一行 gctrace 的全貌：
cd /tmp/gbrt3/gcmatrix
GOTOOLCHAIN=go1.27.0 GODEBUG=gctrace=1 ./gcmatrix 5000000
gc 1 @0.000s 4%: 0.022+0.73+0.017 ms clock, 0.22+0.030/0.48/0.32+0.17 ms cpu, 3->4->2 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 2 @0.002s 6%: 0.009+1.2+0.014 ms clock, 0.094+0.052/1.2/0+0.14 ms cpu, 4->5->3 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 3 @0.004s 6%: 0.019+2.5+0.002 ms clock, 0.19+2.0/0.078/0+0.023 ms cpu, 6->7->5 MB, 7 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 4 @0.008s 6%: 0.015+5.1+0.015 ms clock, 0.15+0.12/4.2/0.91+0.15 ms cpu, 10->12->9 MB, 11 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 5 @0.015s 7%: 0.012+10+0.006 ms clock, 0.12+0.24/10/0.012+0.068 ms cpu, 16->20->15 MB, 19 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 6 @0.028s 8%: 0.026+20+0.004 ms clock, 0.26+0.49/20/0.003+0.048 ms cpu, 26->31->23 MB, 30 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 7 @0.054s 8%: 0.019+36+0.004 ms clock, 0.19+0.93/36/0.003+0.042 ms cpu, 42->50->37 MB, 47 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 8 @0.098s 8%: 0.022+66+0.010 ms clock, 0.22+1.5/65/0.70+0.10 ms cpu, 67->79->59 MB, 75 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 9 @0.179s 8%: 0.020+106+0.007 ms clock, 0.20+20/85/0.003+0.070 ms cpu, 106->125->94 MB, 119 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 10 @0.308s 9%: 0.026+189+0.68 ms clock, 0.26+4.9/188/0.028+6.8 ms cpu, 167->200->150 MB, 188 MB goal, 0 MB stacks, 0 MB globals, 10 P
n=5000000 wall=535ms numGC=10 pauseTotalMs=0.96 heapAllocMB=275.3 heapSysMB=289.0 totalAllocMB=400.2
把 gc 10 那行拆开读：
@0.308s：从程序启动到本次 GC 开始的时刻。9%：到此刻为止 GC 占用的 CPU 比例。0.026+189+0.68 ms clock：三个阶段的墙钟耗时——STW（终止清扫）、并发标记、STW（标记终止）。注意中间那 189 ms 是并发的，不阻塞用户 goroutine。0.26+4.9/188/0.028+6.8 ms cpu：对应的 CPU 时间；中间三项用/分隔，分别是辅助标记（assist）、后台标记、空闲标记。167->200->150 MB：本次 GC 开始时的堆、结束时的堆、标记后的存活堆。188 MB goal：下一次 GC 的目标堆大小。10 P：参与本次 GC 的 P 数量。
为了验证「goal = 存活堆 × (1 + GOGC/100)」，用同一程序换三个 GOGC 值看 goal 列：
for g in 50 100 200; do
echo "== GOGC=$g =="
env GOGC=$g GODEBUG=gctrace=1 ./gcmatrix 3000000 2>&1 | grep "^gc " | tail -4
done
== GOGC=50 ==
gc 17 @0.317s 9%: 0.026+82+0.007 ms clock, 0.26+2.2/82/0+0.075 ms cpu, 62->71->58 MB, 69 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 18 @0.412s 9%: 0.021+107+0.018 ms clock, 0.21+10/98/0+0.18 ms cpu, 79->90->74 MB, 88 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 19 @0.534s 9%: 0.026+136+0.005 ms clock, 0.26+3.2/136/0+0.056 ms cpu, 100->114->94 MB, 111 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 20 @0.686s 9%: 0.026+173+0.007 ms clock, 0.26+4.9/173/0.020+0.070 ms cpu, 128->145->120 MB, 142 MB goal, 0 MB stacks, 0 MB globals, 10 P
== GOGC=100 ==
gc 10 @0.329s 8%: 0.022+160+0.006 ms clock, 0.22+3.9/159/1.1+0.066 ms cpu, 139->161->120 MB, 153 MB goal, 0 MB stacks, 0 MB globals, 10 P
== GOGC=200 ==
gc 5 @0.164s 8%: 0.028+155+0.006 ms clock, 0.28+5.0/151/2.9+0.068 ms cpu, 154->181->122 MB, 166 MB goal, 0 MB stacks, 0 MB globals, 10 P
验算：GOGC=50 时上一轮存活 94 MB，goal = 94 × 1.5 ≈ 141，实测 142；GOGC=100 时上一轮存活 76 MB，goal = 76 × 2 = 152，实测 153；GOGC=200 时上一轮存活 55 MB，goal = 55 × 3 = 165，实测 166。公式对得上。
用 metrics 量化尾延迟
接下来看延迟。处理器每次调用分配 2 KB 并记录端到端延迟，最后读 runtime/metrics 的三个指标（暂停直方图、调度延迟直方图、GC 周期计数）：
package main
import (
"fmt"
"os"
"runtime/metrics"
"sort"
"strconv"
"time"
)
func handler() []byte {
b := make([]byte, 2048)
for i := 0; i < len(b); i += 64 {
b[i] = byte(i)
}
return b
}
func main() {
n := 200000
if len(os.Args) > 1 {
n, _ = strconv.Atoi(os.Args[1])
}
lat := make([]time.Duration, 0, n)
var sink []byte
for i := 0; i < n; i++ {
t0 := time.Now()
sink = handler()
lat = append(lat, time.Since(t0))
}
_ = sink
sort.Slice(lat, func(i, j int) bool { return lat[i] < lat[j] })
p := func(q float64) time.Duration { return lat[int(float64(len(lat)-1)*q)] }
fmt.Printf("requests=%d p50=%v p99=%v p999=%v max=%v\n",
n, p(0.50).Round(time.Microsecond), p(0.99).Round(time.Microsecond),
p(0.999).Round(time.Microsecond), lat[len(lat)-1].Round(time.Microsecond))
names := []string{"/gc/pauses:seconds", "/sched/latencies:seconds", "/gc/cycles/total:gc-cycles"}
samples := make([]metrics.Sample, len(names))
for i, nm := range names {
samples[i].Name = nm
}
metrics.Read(samples)
var gcPauses, schedLat, gcCycles uint64
for _, s := range samples {
switch s.Name {
case "/gc/pauses:seconds", "/sched/latencies:seconds":
var total uint64
for _, c := range s.Value.Float64Histogram().Counts {
total += c
}
if s.Name == "/gc/pauses:seconds" {
gcPauses = total
} else {
schedLat = total
}
case "/gc/cycles/total:gc-cycles":
gcCycles = s.Value.Uint64()
}
}
fmt.Printf("gcPauses=%d schedLat=%d gcCycles=%d\n", gcPauses, schedLat, gcCycles)
}
每种配置重复 5 次，取区间：
cd /tmp/gbrt3/metrics2
GOTOOLCHAIN=go1.27.0 go build -o m2 .
for cfg in "GOGC=off" "GOGC=100" "GOGC=1000"; do
echo "== $cfg =="
for r in 1 2 3 4 5; do env $cfg ./m2 200000; done
done
== GOGC=off ==
requests=200000 p50=0s p99=3µs p999=9µs max=157µs
gcPauses=0 schedLat=2 gcCycles=0
requests=200000 p50=0s p99=2µs p999=7µs max=44µs
gcPauses=0 schedLat=2 gcCycles=0
requests=200000 p50=0s p99=2µs p999=7µs max=45µs
gcPauses=0 schedLat=2 gcCycles=0
requests=200000 p50=0s p99=2µs p999=10µs max=46µs
gcPauses=0 schedLat=2 gcCycles=0
requests=200000 p50=0s p99=2µs p999=8µs max=56µs
gcPauses=0 schedLat=1 gcCycles=0
== GOGC=100 ==
requests=200000 p50=0s p99=3µs p999=29µs max=1.053ms
gcPauses=356 schedLat=549 gcCycles=178
requests=200000 p50=0s p99=2µs p999=30µs max=116µs
gcPauses=368 schedLat=568 gcCycles=184
requests=200000 p50=0s p99=2µs p999=28µs max=97µs
gcPauses=374 schedLat=608 gcCycles=187
requests=200000 p50=0s p99=2µs p999=29µs max=127µs
gcPauses=376 schedLat=583 gcCycles=188
requests=200000 p50=0s p99=2µs p999=32µs max=107µs
gcPauses=374 schedLat=578 gcCycles=187
== GOGC=1000 ==
requests=200000 p50=0s p99=2µs p999=4µs max=152µs
gcPauses=20 schedLat=33 gcCycles=10
requests=200000 p50=0s p99=1µs p999=4µs max=148µs
gcPauses=20 schedLat=34 gcCycles=10
requests=200000 p50=0s p99=1µs p999=3µs max=210µs
gcPauses=20 schedLat=30 gcCycles=10
requests=200000 p50=0s p99=1µs p999=4µs max=216µs
gcPauses=20 schedLat=35 gcCycles=10
requests=200000 p50=0s p99=1µs p999=3µs max=148µs
gcPauses=20 schedLat=32 gcCycles=10
5 次重复给出的区间很能说明问题：GOGC=100 的 20 万次请求触发 178–188 次 GC，p999 稳定在 28–32 微秒，但最大值在 97 微秒到 1.053 毫秒之间大幅跳动；对照 GOGC=off 只有 44–157 微秒、GOGC=1000 是 148–216 微秒。GOGC=100 那条毫秒级长尾远大于自己的 p999，几乎一定是某次 GC 周期里的调度抖动，而不是单次请求本身的成本。再看 gcPauses 事件数：GOGC=100 有 356–376 个暂停事件，GOGC=1000 只有 20 个，off 为 0——GC 频率与长尾出现的概率直接挂钩。
用 runtime/trace 看事件足迹
再换一个工具确认 GC 周期的真实密度。下面这段程序把 30 万次分配录进 trace：
cd /tmp/gbrt3/traceprog
GOTOOLCHAIN=go1.27.0 go build -o traceprog . && ./traceprog
GOTOOLCHAIN=go1.27.0 go tool trace -d=footprint trace.out | head -25
Event Bytes % Count %
- - - - -
HeapAlloc 624977 89.48% 104132 87.54%
GCSweepEnd 22461 3.22% 3687 3.10%
GCSweepBegin 11064 1.58% 3687 3.10%
GoStart 5697 0.82% 1224 1.03%
ProcStart 5539 0.79% 1045 0.88%
STWBegin 904 0.13% 201 0.17%
HeapGoal 606 0.09% 101 0.08%
GCMarkAssistBegin 450 0.06% 150 0.13%
STWEnd 440 0.06% 201 0.17%
GCBegin 436 0.06% 100 0.08%
GCMarkAssistEnd 391 0.06% 150 0.13%
GCEnd 337 0.05% 100 0.08%
trace 文件 682 KB。30 万次分配里有 10.4 万次 HeapAlloc 事件（只有逃逸到堆的分配才被记录），100 个完整 GC 周期（GCBegin/GCEnd），201 对 STWBegin/STWEnd，以及 150 次 GCMarkAssistBegin——辅助标记的绝对次数已经超过 STW 的 201 的一半，这正是尾延迟里最容易被忽略的一项。
7.2.2 源码：gctrace 的每一列与 pacing 算法
gctrace 那一行不是凭空拼的，它的打印语句在 src/runtime/mgc.go 的 gcMarkTermination 末尾：
// src/runtime/mgc.go:gcMarkTermination（节选，约 1588 行）
if debug.gctrace > 0 {
util := int(memstats.gc_cpu_fraction * 100)
...
print("gc ", memstats.numgc,
" @", string(itoaDiv(sbuf[:], uint64(work.tSweepTerm-runtimeInitTime)/1e6, 3)), "s ",
util, "%")
...
print(" ms clock, ")
for i, ns := range []int64{
int64(work.stwprocs) * (work.tMark - work.tSweepTerm),
gcController.assistTime.Load(),
gcController.dedicatedMarkTime.Load() + gcController.fractionalMarkTime.Load(),
gcController.idleMarkTime.Load(),
int64(work.stwprocs) * (work.tEnd - work.tMarkTerm),
} {
...
}
print(" ms cpu, ",
work.heap0>>20, "->", work.heap1>>20, "->", work.heap2>>20, " MB, ",
gcController.lastHeapGoal>>20, " MB goal, ",
gcController.lastStackScan.Load()>>20, " MB stacks, ",
gcController.globalsScan.Load()>>20, " MB globals, ",
work.maxprocs, " P")
对照着读：assistTime 就是辅助标记的 CPU 时间（ms cpu 里 / 分隔的第一项），dedicatedMarkTime + fractionalMarkTime 是后台标记，idleMarkTime 是空闲标记，lastHeapGoal 就是 goal 列。
pacing 的核心是 endCycle：每个 GC 周期结束时，它用「本轮实际观测到的分配速度 / 标记速度」更新下一轮的 runway。
// src/runtime/mgcpacer.go:endCycle（节选，约 598 行）
func (c *gcControllerState) endCycle(now int64, procs int) {
// Record last heap goal for the scavenger.
gcController.lastHeapGoal = c.heapGoal()
assistDuration := now - c.markStartTime
utilization := gcBackgroundUtilization
if assistDuration > 0 {
utilization += float64(c.assistTime.Load()) / float64(assistDuration*int64(procs))
}
...
}
revise 则在周期进行中实时调整辅助标记的比例（assist ratio），它决定了用户 goroutine 每分配多少字节就要替 GC 干多少活：
// src/runtime/mgcpacer.go:revise（节选，约 492 行）
func (c *gcControllerState) revise() {
gcPercent := c.gcPercent.Load()
if gcPercent < 0 {
gcPercent = 100000 // GC 被禁用时的近似值
}
live := c.heapLive.Load()
scan := c.heapScan.Load()
...
heapGoal := int64(c.heapGoal())
...
}
最终决定「下一轮什么时候开始」的仍是 heapGoalInternal（见 7.1 的源码片段）：GOGC 目标与内存上限目标取小者，再叠加 minRunway 等修正。
7.2.3 决策：延迟分析清单
把上面的实验与源码压成一份可照做的清单：
| 现象 | 先看什么 | 判据 |
|---|---|---|
| P99/P999 有微秒级毛刺 | /gc/pauses:seconds 直方图 | 暂停集中在 10–40 微秒属正常，超过 1 ms 才值得追 |
| 偶发毫秒级长尾 | 请求延迟最大值 vs numGC | 若长尾数量级 ≈ GC 周期数，八成是 GC 辅助标记或调度抖动 |
| CPU 被 GC 吃掉 | gctrace 的 N% 列 | 该列 > 10% 说明标记/辅助在抢 CPU，考虑调 GOGC 或减少分配 |
| 不确定毛刺来源 | runtime/trace 的 GCMarkAssistBegin 计数 | 辅助标记次数逼近 STW 次数时，瓶颈在分配速度而非 STW |
| 内存锯齿剧烈 | gctrace 的 goal 列 | goal 远高于存活堆说明 GOGC 偏大，可下调换延迟 |
三条纪律：
- 先量再改：
GOGC=off与GOGC=1000的对照（最大值 44–157 微秒 vs 1000 的 148–216 微秒，而默认GOGC=100能冲到 1.053 毫秒）说明，任何「GC 拖慢了服务」的判断都必须用这种 A/B 对照来证实。 - 盯辅助标记，不只盯 STW：Go 的 STW 已经压到亚毫秒，尾延迟的大头往往在辅助标记与调度延迟，
/sched/latencies:seconds直方图要一起看。 gctrace只用于定性：它给的是周期级聚合，单次暂停的分布要靠/gc/pauses:seconds直方图，两者互补。
阅读导航：上一节：7.1 GOGC/GOMEMLIMIT 实验矩阵 · 下一节：7.3 减少分配与 GC 压力 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。