《Go 性能诊断：pprof 与执行追踪》

要做什么，不做什么

给性能问题立一条流水线：先 benchmark 确认”慢不慢”，再用 pprof 回答”慢在哪”，锁相关的怀疑交给 mutex/block profile，调度层面的疑案交给 trace。诊断对象就用站内那个缓存——《用 Go 写一个并发安全的内存缓存》的产出，正好把那篇留下的”压测口径”补成完整流程。边界先说死：不做内存逃逸分析专题；不做 GOGC/GOMEMLIMIT 调参；火焰图工具链只讲到官方 pprof 自带的为止；文中所有 profile 与 benchstat 输出均为格式示意，不是实测数据——数字随机器和负载漂移，读图看占比与趋势，别抄绝对值。版本口径：Go 1.23（2024-08-13 GA）。

先测量，再动手

性能工作最大的坑不在技术，在顺序：凭直觉优化的人，十次有九次优化在没人感知的地方。我的顺序固定三步：benchmark 确认瓶颈存在且可复现 → profile 找到热点函数 → 改一处，benchstat 验证，不显著就回滚。

给缓存先立一个基准，拿那篇文章的 Get 来测：

func BenchmarkCacheGet(b *testing.B) {
    c := New(time.Minute, 1<<20)
    defer c.Close()
    for i := range 10000 {
        c.Set(strconv.Itoa(i), i)
    }
    b.ResetTimer()
    b.ReportAllocs()
    for i := 0; i < b.N; i++ {
        c.Get(strconv.Itoa(i%10000))
    }
}

$ go test -bench . -benchmem -count=10 > old.txt

-count=10 跑十遍是给 benchstat 攒样本——单次跑的数字波动能到两位数百分比，十次的分布才敢下结论。-benchmem 顺手记下每操作的分配次数与字节数：内存问题在 CPU 图里看不清，分配次数的一升一降反而灵敏。

benchstat：改动的裁判

改完代码跑出 new.txt，裁判交给官方工具 benchstat：

go install golang.org/x/perf/cmd/benchstat@latest
benchstat old.txt new.txt

输出长这样（示意格式，数字是编的形状，看结构别看值）：

goos: darwin
goarch: arm64
        │  old.txt   │           new.txt            │
        │   sec/op   │   sec/op     vs base         │
Get-8     123.4n ± 3%   98.7n ± 2%  -20.00% (p=0.000 n=10)

读法三句话：±3% 是波动带，波动大说明基准本身不稳，先回去修基准；vs base 那列才是结论；p=0.000 是统计显著性，p 大于 0.05 的”提升”当噪声处理。没有这两列兜底，性能优化很容易变成自我安慰。

还有个前置问题：瓶颈”成立”的标准是什么？不是 ns/op 好不好看，是业务症状——P95 长尾、目标吞吐达不到、资源饱和。先有症状，再去测量；没有症状的优化是爱好，不是工程。

pprof 四类 profile，各回答一个问题

服务里挂上 pprof 只需要一行 import（别把端口裸暴露到公网）：

import _ "net/http/pprof" // 注册到 DefaultServeMux 的 /debug/pprof/

读图前先懂采样原理，免得对着数字较劲。CPU profile 是采样制：默认每秒 100 次停下程序看一眼调用栈，谁的栈出现得多谁占的时间多——它回答的是占比而非绝对值，30 秒约 3000 份样本，样本少则抖动大。heap 默认按分配大小抽样（MemProfileRate，默认每 512KB 记一次），看到的是代表性样本而非全量账本——heap 数字和粗算的常驻内存对不齐是正常的，看相对变化就好。

CPU profile：时间花在哪

采 30 秒 CPU 数据并直接进交互界面：

go tool pprof -http=:8081 http://localhost:6060/debug/pprof/profile?seconds=30

先看 top：flat 是函数自身耗时，cum 是”自己加被它调用的”累计耗时——flat 高是热点本体，cum 高要往下钻调用链；list 函数名 把耗时分摊到源码行。Flame graph（界面里 View → Flame graph）看整体形状：又宽又矮的横条是正常态，一条又高又窄的竖线通常意味着某条调用路径独占了时间。基准代码不用起服务也能出 profile：go test -bench . -cpuprofile cpu.out，然后 go tool pprof cpu.out。

heap profile：内存谁在吃

go tool pprof -http=:8081 http://localhost:6060/debug/pprof/heap

默认看 inuse_space（当前驻留），查泄漏看 alloc_space（累计分配）配合两次采样对比：pprof 交互里 base 命令把早先的采样设为基线，增量全在图里。Go 里的内存泄漏多数不是”忘 free”，是”本该死的对象还被引用着”——goroutine 持有、全局 map 只进不出、timer 忘了 Stop，都是常见凶手。

goroutine profile：谁在堆积

curl -s "http://localhost:6060/debug/pprof/goroutine?debug=2" | head -50

排查泄漏的第一现场：文本直出每个 goroutine 的栈与阻塞位置，一眼能看到”几千个 goroutine 全部卡在同一个 chan receive”。数量突增是事故前兆，值得在告警里盯一份。

mutex 与 block：锁在偷时间吗

这两个 profile 默认关闭，要显式打开：

runtime.SetMutexProfileFraction(1) // 1 表示全采样
runtime.SetBlockProfileRate(1)     // 单位纳秒，1 表示全记录

mutex profile 回答”谁持锁太久、谁在等锁”；block profile 覆盖更广的阻塞面（channel、锁、select）。对”CPU 不高但吞吐上不去”的服务，先看这两个——CPU 图一片祥和而 QPS 上不去，时间多半耗在排队。基准场景下也有对应出口：go test -bench . -mutexprofile mutex.out。

完整走一遍：诊断那个缓存

把流程串起来。第一轮 benchmark 跑完，我没有直接改代码，先出 CPU profile 读图。读之前先立预期：这份缓存是”一把全局锁守一个 map”的写法，读多写少场景下锁竞争是否构成瓶颈是它自己立下的验收问题，所以图里应该能看到几个名字——runtime.mapaccess（map 查找）、锁相关的 sync.Mutex.Lock、janitor 的 evictLocked。

诊断的乐趣在于让数据说话。CPU 图干净、耗时大头落在 map 访问上，说明单锁在千级条目下确实不构成瓶颈——这正是那篇文章压测一节的定性结论，profile 给了它第二重证据；反过来，如果 mutex profile 里等待时间集中，才轮到分片锁出场。顺序反了——先写分片再测量——大概率白忙一场。

回源慢的现场：换一把工具

CPU profile 有个盲区：等待不是计算。构造一个现场——一百个 goroutine 并发 GetOrLoad 同一个 key，load 函数里睡 50 毫秒模拟慢回源：

c := New(time.Minute, 1<<20)
defer c.Close()
var wg sync.WaitGroup
for range 100 {
    wg.Add(1)
    go func() {
        defer wg.Done()
        c.GetOrLoad("hot-key", func() (any, error) {
            time.Sleep(50 * time.Millisecond) // 模拟慢回源
            return 42, nil
        })
    }()
}
wg.Wait()

此刻开 CPU profile，图里几乎没有 load 的影子——时间都花在睡眠和排队上，CPU 是闲的。换 goroutine profile（?debug=2），能看到大量 goroutine 停在同一个等待点；block profile 把这段等待时间量化出来；singleflight 的去重效果则体现在 load 只执行一次。这组对照是四类 profile 分工的最好教材：计算问题找 CPU 图，等待问题找 goroutine/block，内存问题找 heap——先对症，再采样。

题外一条与 Go 1.23 相关：从这版起，timer 和 Ticker 只要程序里不再有引用，就能被 GC 立即回收，哪怕忘了调 Stop。janitor 那个 time.NewTicker 从此少一个”Close 之前忘了 Stop 会不会拖住 GC”的心结——老版本里这可是正经的泄漏源。

trace：调度延迟的显微镜

profile 回答”谁占了时间”，trace 回答”时间在什么时候断档”。服务 goroutine 明明不忙，请求却时不时抖一下——这类调度层面的疑案，CPU profile 是瞎的，trace 能看见：

go test -trace trace.out -bench .   # 或代码里 trace.Start / trace.Stop
go tool trace trace.out             # 打开浏览器界面

界面里我最常看两处：Scheduler latency profile——goroutine 从”可运行”到”真的上 CPU”的等待时间分布，p95 突然抬高就是调度压力实锤；Goroutine analysis——按状态拆解每类 goroutine 的生命周期，阻塞在 IO、锁还是调度一目了然。快速抓现场还有个土办法：GODEBUG=schedtrace=1000 让 runtime 每秒打印一次调度器脉搏，先粗判再上 trace。profile 与 trace 的分工记一句：profile 是”谁的账”，trace 是”什么时候断的档”——抖动类问题（周期性卡顿、偶发超时）优先 trace，稳定偏慢优先 profile。

验收清单

• benchmark 带 -benchmem -count=10 跑出 old.txt，样本分布稳定；
• benchstat 对比改动前后，vs base 列与 p 值都在，无显著差异的”优化”已回滚；
• 本地起服务，CPU/heap/goroutine/mutex 四种 profile 各采一次样，各自读出一条具体结论；
• go test -bench . -cpuprofile cpu.out 产出的 profile 能被 pprof 打开并定位到源码行；
• trace 跑通，能说出 Scheduler latency 的量级与 Goroutine analysis 的主要阻塞点；
• /debug/pprof/ 未暴露到公网（防火墙或独立内网端口）。

学完之后

诊断是性能工作的入场券，优化手段是后面的课：分片锁、sync.Pool 复用、批量合并，每个都值得单开一篇。动手的底子——goroutine 调度、channel 语义、race 检测——《Go 并发基础》已经铺好；被诊断的那个缓存从选型到验收的完整过程在《用 Go 写一个并发安全的内存缓存》。两篇对着读，”测量 → 定位 → 验证”的流程才算贯通。

本文数据核对时间：2024-08-19：Go 1.23（2024-08-13 GA；timer/Ticker 无引用即可被 GC 回收的语义变化随本版生效）；benchstat 属 golang.org/x/perf/cmd/benchstat，安装取 latest；net/http/pprof、go tool pprof 与 runtime/trace 随标准工具链分发；文中 benchstat 与 profile 输出均为格式示意，非实测数据。