15.5 pprof (CPU / 内存 / 阻塞 / 互斥)

一句话

pprof 不是“一个工具”,而是五种数据源:CPU、堆、goroutine、阻塞、互斥;选错 profile 等于用体温计量血压——先问“我要看的是时间、内存、还是等待”,再决定采哪一个。

先破除四个误区

误区 现实
“抓一次 CPU profile 就能看所有问题” CPU profile 只统计在 CPU 上跑的样本;等锁、等 IO、等 channel 的代码在它眼里是“不存在”的
“profile 是精确值” 采样剖析有统计误差:100Hz × 30s ≈ 3,000 个样本,1% 的差异可能只是噪声
“生产不能开 pprof” CPU profile 通常 <5% 开销,heap 更低;但端点必须鉴权/内网,不能裸奔
“会看火焰图就会定位” 火焰图只回答“时间花在哪”;“为什么等、等了多久”要看 block/mutex/off-CPU(见 15.9 性能剖析工具链 (火焰图 / perf / eBPF))

五种 profile,五个问题

方法层面的选择(何时用哪种、怎么读图)在 34.3 性能分析方法 (火焰图 / pprof / perf);这里只讲 Go 的实现细节与操作。

Profile 回答 采样/开销 关键开关
CPU on-CPU 时间花在哪些函数 100Hz 采样,通常 <5% -cpuprofile、?seconds=30
Heap 谁在分配、谁还持有内存 每 512KB 采样一次,低开销 alloc_space / inuse_space
Goroutine 现在有多少 goroutine、卡在哪 全量快照,低开销 debug=1 / debug=2
Block 等 channel/mutex/select 多久 默认关闭,需设 rate SetBlockProfileRate
Mutex 锁竞争多严重、谁持有久 默认关闭,需设 fraction SetMutexProfileFraction

两个默认值最容易踩坑:block 与 mutex 的采样率默认是 0(不采集),所以“抓了 profile 却什么都没有”不是没竞争,是没开。

三种采集方式

方式 适用 代码/命令
net/http/pprof 常驻服务,临时抓 import _ "net/http/pprof" + 独立端口
runtime/pprof CLI 工具、一次性任务 pprof.StartCPUProfile(w)
go test 参数 基准测试、复现实验 -cpuprofile / -memprofile / -blockprofile / -mutexprofile
// 常驻服务:把 pprof 放在独立的 admin 端口,不要和业务端口混在一起
import (
	"net/http"
	_ "net/http/pprof" // 注册 /debug/pprof/*
)

func main() {
	go func() {
		// 只监听内网/回环;生产必须加鉴权或走跳板
		http.ListenAndServe("127.0.0.1:6060", nil)
	}()
	// ... 业务
}
端点 作用 常用参数
/debug/pprof/profile CPU ?seconds=30
/debug/pprof/heap 堆 ?sample_index=alloc_space(pprof 侧)
/debug/pprof/goroutine goroutine ?debug=1(聚合)/debug=2(全栈)
/debug/pprof/block 阻塞 需先设 rate
/debug/pprof/mutex 互斥 需先设 fraction
/debug/pprof/trace 调度/GC 时序 ?seconds=5,用 go tool trace 打开

goroutine 数量异常、调度延迟高的分析见 15.1 GMP 调度模型;系统调用/内核态/调度的观测见 11.7 eBPF 与内核态观测。

⚠️ pprof 端点会暴露调用栈、参数、部分内存信息。生产上只开在回环/内网,加认证与速率限制;不要用公网域名直接暴露 /debug/pprof。

一份能跑的基准:四种 profile 都采到

package ppdemo

import (
	"crypto/sha256"
	"sync"
	"testing"
)

var buf = make([]byte, 4096)

// hotHash:让 CPU 真正花在 sha256 上,而不是 GC。
func hotHash(n int) {
	var sum [32]byte
	for i := 0; i < n; i++ {
		sum = sha256.Sum256(buf)
		buf[0] = sum[0]
	}
}

// allocHot:制造稳定的堆分配,用来看 alloc_space。
func allocHot(n int) [][]byte {
	out := make([][]byte, 0, n)
	for i := 0; i < n; i++ {
		out = append(out, make([]byte, 1024))
	}
	return out
}

var (
	mu      sync.Mutex
	counter int
)

func BenchmarkHash(b *testing.B) {
	for i := 0; i < b.N; i++ {
		hotHash(64)
	}
}

var sinkAlloc [][]byte

func BenchmarkAlloc(b *testing.B) {
	for i := 0; i < b.N; i++ {
		sinkAlloc = allocHot(4096) // 保留最后一批(约 4MB),让 inuse 里能看到它
	}
}

func BenchmarkMutex(b *testing.B) {
	var wg sync.WaitGroup
	for g := 0; g < 8; g++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for i := 0; i < b.N; i++ {
				mu.Lock()
				counter++
				mu.Unlock()
			}
		}()
	}
	wg.Wait()
}

func BenchmarkBlock(b *testing.B) {
	ch := make(chan int)
	go func() {
		for range ch {
		}
	}()
	for i := 0; i < b.N; i++ {
		ch <- i
	}
	close(ch)
}

采集命令(每个 benchmark 单独跑,避免互相污染):

# CPU
go test -run '^$' -bench '^BenchmarkHash$' -benchtime=1s -cpuprofile=cpu.out
go tool pprof -top -nodecount=8 cpu.out

# 堆:alloc_space(分配总量)与 inuse_space(当前存活)
go test -run '^$' -bench '^BenchmarkAlloc$' -benchtime=200ms -memprofile=mem.out
go tool pprof -top -nodecount=5 -sample_index=alloc_space mem.out
go tool pprof -top -nodecount=5 -sample_index=inuse_space mem.out

# 阻塞
go test -run '^$' -bench '^BenchmarkBlock$' -benchtime=300ms -blockprofile=block.out
go tool pprof -top -nodecount=6 block.out

# 互斥
go test -run '^$' -bench '^BenchmarkMutex$' -benchtime=300ms -mutexprofile=mutex.out
go tool pprof -top -nodecount=6 mutex.out

本机实测(Go 1.27,Apple M1;本机 Go 安装缺少 pprof 工具,以下输出由同版本源码构建的 pprof 得到,命令与 go tool pprof 等价):

$ go tool pprof -top -nodecount=8 cpu.out
File: pp.test
Type: cpu
Duration: 2.22s, Total samples = 1.84s (83.01%)
Showing nodes accounting for 1.84s, 100% of 1.84s total
      flat  flat%   sum%        cum   cum%
     1.80s 97.83% 97.83%      1.80s 97.83%  crypto/internal/fips140/sha256.blockSHA2
     0.01s  0.54% 98.37%      0.01s  0.54%  runtime.kevent
     0.01s  0.54% 98.91%      0.01s  0.54%  runtime.pidleget
     0.01s  0.54% 99.46%      0.01s  0.54%  runtime.pthread_cond_signal
     0.01s  0.54%   100%      0.01s  0.54%  runtime.pthread_mutex_lock
         0     0%   100%      1.80s 97.83%  _/tmp/luban15/pp.BenchmarkHash
         0     0%   100%      1.80s 97.83%  _/tmp/luban15/pp.hotHash
         0     0%   100%      0.02s  1.09%  crypto/internal/fips140/sha256.(*Digest).Sum

注意 hotHash 的 flat = 0、cum = 1.80s:它被内联了,自身没有独立样本,但累计时间都算在它头上。看到 0 不代表没执行,先看 cum 与 -list。

$ go tool pprof -top -nodecount=5 -sample_index=alloc_space mem.out
File: pp.test
Type: alloc_space
Showing nodes accounting for 3.67GB, 99.95% of 3.68GB total
      flat  flat%   sum%        cum   cum%
    3.67GB 99.95% 99.95%     3.67GB 99.95%  _/tmp/luban15/pp.allocHot (inline)
         0     0% 99.95%     3.67GB 99.95%  _/tmp/luban15/pp.BenchmarkAlloc
         0     0% 99.95%     3.67GB 99.89%  testing.(*B).launch
         0     0% 99.95%     3.67GB 99.95%  testing.(*B).runN

$ go tool pprof -top -nodecount=4 -sample_index=inuse_space mem.out
File: pp.test
Type: inuse_space
Showing nodes accounting for 6151.05kB, 100% of 6151.05kB total
      flat  flat%   sum%        cum   cum%
    4100kB 66.66% 66.66%     4100kB 66.66%  _/tmp/luban15/pp.allocHot (inline)
 2051.05kB 33.34%   100%  2051.05kB 33.34%  runtime.mallocgc
         0     0%   100%     4100kB 66.66%  _/tmp/luban15/pp.BenchmarkAlloc
         0     0%   100%   512.05kB  8.32%  runtime.(*scavengerState).init

alloc_space = 3.67GB、inuse_space = 4.1MB:分配总量是流量,存活量是库存。看“内存泄漏”用 inuse_space,看“GC 压力”用 alloc_space。

$ go tool pprof -top -nodecount=6 block.out
File: pp.test
Type: delay
Showing nodes accounting for 1018.74ms, 100% of 1018.74ms total
      flat  flat%   sum%        cum   cum%
  608.21ms 59.70% 59.70%   608.21ms 59.70%  runtime.chanrecv1
  206.23ms 20.24% 79.95%   206.23ms 20.24%  runtime.chanrecv2
  204.30ms 20.05%   100%   204.30ms 20.05%  runtime.chansend1
         0     0%   100%   204.30ms 20.05%  _/tmp/luban15/pp.BenchmarkBlock
         0     0%   100%   206.23ms 20.24%  _/tmp/luban15/pp.BenchmarkBlock.func1
         0     0%   100%   608.21ms 59.70%  main.main
$ go tool pprof -top -nodecount=6 mutex.out
File: pp.test
Type: delay
Showing nodes accounting for 1253.62ms, 100% of 1254ms total
      flat  flat%   sum%        cum   cum%
 1104.87ms 88.11% 88.11%  1173.38ms 93.57%  sync.(*Mutex).Unlock (inline)
  148.75ms 11.86%   100%   148.75ms 11.86%  runtime.unlock (inline)
         0     0%   100%  1212.42ms 96.68%  _/tmp/luban15/pp.BenchmarkMutex.func1
         0     0%   100%    39.04ms  3.11%  internal/sync.(*Mutex).Lock (inline)
         0     0%   100%    68.51ms  5.46%  internal/sync.(*Mutex).Unlock (inline)
         0     0%   100%    39.04ms  3.11%  internal/sync.(*Mutex).lockSlow

mutex profile 最反直觉的一点:flat 最大的往往是 Unlock 而不是 Lock。Go 把“等锁的时间”记在持锁者释放锁的位置(谁持有、谁导致等待),所以要看 cum 链路去找真正的持锁代码,别盯着 Unlock 本身。

pprof 命令:五个够用

命令 回答 例子
top 谁最耗时/最占内存 pprof -top -nodecount=20 cpu.out
list 这个函数的哪一行热 pprof -list='hotHash' cpu.out
peek 谁调用它、它调用谁 pprof -peek='blockSHA2' cpu.out
traces 具体调用栈样本 pprof -traces cpu.out
web / -http 图形化(需要 graphviz) pprof -http=:8081 cpu.out

差异对比(优化前后):

# 同负载、同机器、同时长
go tool pprof -proto -output=before.pb.gz 'http://svc:6060/debug/pprof/profile?seconds=30'
go tool pprof -proto -output=after.pb.gz  'http://svc:6060/debug/pprof/profile?seconds=30'
go tool pprof -diff_base=before.pb.gz -http=:8081 after.pb.gz

标签(把“哪个租户/接口/分片”带进 profile):

ctx = pprof.WithLabels(ctx, pprof.Labels("route", "/checkout", "tenant", tenantID))
pprof.Do(ctx, pprof.Labels(), func(ctx context.Context) {
	handle(ctx) // 这段调用栈会带上 label
})

差异图与标签是 pprof 最被低估的两个能力:前者回答“优化有没有用”,后者回答“慢的是谁”。

五个坑

坑 现象 正确做法
服务空闲时抓 CPU 样本几乎全是 runtime/GC 噪声 在有负载时抓,或看 -focus;空闲时改看 block/goroutine
把采样当精确值 1% 的差异反复纠结 样本 ≥ 3,000(30s@100Hz),关注 ≥5% 的差异
内联导致 0 flat 函数“看不到” 看 cum、用 -list、必要时 -gcflags='-l' 关闭内联复现
block/mutex 为空 以为没竞争 生产代码要设 SetBlockProfileRate(1) / SetMutexProfileFraction(1),或改用 go test -blockprofile/-mutexprofile
只看 alloc_space 以为内存泄漏 泄漏看 inuse_space;分配压力看 alloc_space

生产落地:指名 → 可抄 → 可验 → 可退

指名:常驻服务用标准库 net/http/pprof;需要长期采集/对比用 Pyroscope 或 Parca(见 50.8 持续性能剖析);GC 相关调优见 15.4 GC 原理与调优 (GOGC / GOMEMLIMIT)。

可抄:

# 线上抓 30 秒 CPU(端点只在内网)
go tool pprof -top -nodecount=20 'http://10.0.0.12:6060/debug/pprof/profile?seconds=30'

# 抓堆并对比两次
curl -s -o heap1.pb.gz 'http://10.0.0.12:6060/debug/pprof/heap'
curl -s -o heap2.pb.gz 'http://10.0.0.12:6060/debug/pprof/heap'
go tool pprof -top -sample_index=inuse_space -diff_base=heap1.pb.gz heap2.pb.gz

可验:本节四个 profile 都真跑过,输出如上;验证点是“能复现同样的热点/分配/阻塞/竞争”。线上至少验证:抓取时 CPU 开销可接受(灰度实例先试)、堆 profile 的 inuse_space 与监控 RSS 趋势一致、block/mutex 在开启采样后确实有数据。

可退:pprof 本身无状态,停止抓取即恢复;如果采样开销影响服务,降低频率/缩短时长、只在单实例开启。开启 block/mutex 采样会增加开销,生产先用低 fraction(如 1/100)观察。

反模式

反模式 后果
在空闲实例上抓 CPU profile 全是噪声,得出“代码没问题”的错误结论
用 alloc_space 判断内存泄漏 把“分配多”误判为“泄漏”
看到 Unlock 占比高就去优化 Unlock 真正的问题是持锁时间长/临界区大
生产裸奔 /debug/pprof 调用栈、参数、内存信息泄露
只抓一次、不看负载/版本 无法复现,也无法对比
用单次 1% 差异下结论 采样误差大于差异
把 pprof 当 trace 用 看不到调度/GC 时序,要用 go tool trace

自检

Q1 为什么 CPU profile 里“等数据库”的代码几乎不出现?

▸ 答案:CPU profile 以 100Hz 采样“当前在 CPU 上运行的栈”,等数据库时 goroutine 处于阻塞/休眠,不在 CPU 上,因此不会被采到。这种问题要用 block profile(等 channel/mutex)、off-CPU(perf/eBPF)或链路追踪定位,不能靠 CPU 火焰图。

Q2 alloc_space 和 inuse_space 分别回答什么问题?

▸ 答案:alloc_space 是采样周期内的分配总量(流量),回答“GC 压力大不大、谁在频繁分配”;inuse_space 是采样时刻仍存活的对象(库存),回答“谁在持有内存、有没有泄漏”。判断泄漏看 inuse 随时间的增长,判断分配压力看 alloc。

Q3 为什么 mutex profile 的 flat 常常落在 Unlock 上?

▸ 答案:Go 的 mutex profile 记录的是“因竞争而等待”的延迟,并把这段延迟记在释放锁的调用栈上(谁持锁、谁造成等待)。所以 Unlock 的 flat 高,不代表解锁慢,而代表“这把锁的临界区被争抢”。要看 cum 链路和持锁代码,缩小临界区或分片。

Q4 block profile 抓不到数据,最常见的原因是什么?

▸ 答案:采样率默认是 0(关闭)。go test -blockprofile 会自动开启;生产代码需要显式 runtime.SetBlockProfileRate(1)(或一个合适的采样率)。同理 mutex 需要 runtime.SetMutexProfileFraction(1)。没开采样时,“没有数据”不等于“没有阻塞”。

Q5 内联会让 profile 失真吗?怎么处理?

▸ 答案:会。被内联的函数可能没有独立样本,flat=0 但 cum 很高;行号也可能归到调用者。处理:先看 cum 与调用链,用 -list 看源码行;需要精确归因时用 -gcflags='-l' 关闭内联重新编译复现,但要注意这会改变性能特征,只用于定位。

关联