目录
- 一句话与四个角色
- 闹钟与拍肩:一次采样的完整旅程
- 抽查凭什么能代表整体:采样的数学直觉
- 账本与抄账员:样本去哪了,丢了怎么办
- 往账本里夹纸条:标签(tag)是什么
一句话与四个角色
先给一句话版本,全文只是把这句话展开:
CPU 剖析 = 操作系统每 10 毫秒拍一下正在跑的程序肩膀,问"你在干嘛",把答案记进一本无锁账本;另一个 goroutine 定期把账本抄走存成文件;文件里每条"你在干嘛"的答案堆在一起,占比就是你程序的 CPU 时间分布。
拆成四个角色(后面全文用这套称呼):
① 闹钟(内核定时器,每 10ms 一响)
│ POSIX: 发 SIGPROF 信号
│ Windows: profileLoop 线程逐个点名
▼
你的程序 ──────── ② 被拍肩的工人(sigprof() 抓下当前调用栈)
(该干嘛干嘛, │ "我此刻的调用栈" = 一笔账
对被打断无感) │ add():CAS 试一下账本的专用锁,拿不到就放弃这笔
▼
③ 环形账本(profbuf,无锁,写满就撕,绝不等待)
│
▼
④ 抄账员(profileWriter,每 100ms 醒来一次)
│ 抄走 → 编码成 protobuf → cpu.pprof 文件
▼
go tool pprof 读账本、算占比
四个角色各自的"岗位职责",一句话版:
| 角色 | 源码对应 | 岗位职责 | 最重要的约束 |
|---|---|---|---|
| ① 闹钟 | SetCPUProfileRate/setcpuprofilerate | 每 10ms 制造一次打断 | 只负责响,不管谁听到 |
| ② 工人侧 handler | sigprof → cpuprof.add | 抓当前栈,记一笔 | 快进快出:不睡觉、不等锁、不碰堆(见附录 B.1) |
| ③ 账本 | profbuf.go | 攒样本,吸收速度差 | 单写单读无锁;满了丢笔计数(见附录 B.4) |
| ④ 抄账员 | profileWriter + readProfile | 批量取走、编码落盘 | 普通世界,可以用锁、可以分配内存 |
图1:内核定时器(闹钟)每 10ms 拍一次肩 → 被拍肩的工人(
sigprof抓当前调用栈)→ 环形账本(profbuf无锁缓冲)→ 抄账员(profileWriter编码落盘)。配合上面的 ASCII 图一起看,机制就立起来了。
为什么②这么苦大仇深? 因为它跑在信号处理器里——操作系统随时可能在任何两条指令之间叫它上岗,而被打断的代码可能正处于任何中间状态。这三条铁律(不睡觉、不等锁、不碰堆)是理解 03 篇所有源码设计的钥匙,完整论证在附录 B.1。
闹钟与拍肩:一次采样的完整旅程
把 pprof.StartCPUProfile(f) 到 pprof.StopCPUProfile() 之间发生的事,按时间顺序讲一遍。对照 03 篇的源码位置,每一步只讲"发生了什么、为什么"。
**图 **:每 10ms 一次 tick,信号在某一随机时刻拍肩正在运行的代码,抓取当前调用栈入账——这就是"采样"。下面第 0~6 步是它的逐环节拆解。
第 0 步:开工。 你调用 pprof.StartCPUProfile(f)(runtime/pprof/pprof.go:833)。它做三件事:检查"剖析已开启"标志(开着就直接报错——第一层防重入);启一个后台 goroutine 当抄账员④;调 runtime.SetCPUProfileRate(100)。
第 1 步:装闹钟。 SetCPUProfileRate(100)(cpuprof.go:68)→ setcpuprofilerate(proc.go:5569)。100 = 每秒 100 次 = 每 10ms 响一次。POSIX 系统装一个真实定时器,到点内核给进程发 SIGPROF 信号;Windows 没有信号,改由一个专职线程 profileLoop 每 10ms 把所有 Go 线程挨个"点名"(挂起→读栈→恢复,见 03 篇 §十一)。从这一刻起,打断不再经过你代码的同意。
第 2 步:被拍肩。 10ms 后闹钟响了,打断落在某段正在执行的代码上——落在谁头上纯属看运气:哪条 goroutine 正在哪个核上跑,记的就是它。runtime 的信号总入口 sighandler 认出这是 SIGPROF,转给 sigprof()(proc.go:5447)。
第 3 步:抓栈。 sigprof() 的全部工作:从当前线程的寄存器里读出栈指针,顺着栈一帧一帧往外爬,最多 64 帧。这个"正在跑的函数链"就是这笔账的内容——比如 main.busy → main.main → runtime.main。它不看代码、不判断谁"重要",此刻在跑就记谁,这就是"采样"二字的本义。
第 4 步:记账。 cpuprof.add()(cpuprof.go:99)试着往账本③写这笔:
- 先
signalLock.CompareAndSwap试锁——拿不到说明上一笔还没被抄走,直接放弃本笔(绝不等待,附录 B.2 讲透为什么); - 拿到锁后写入:第一笔会先记一条元数据(采样频率 hz,后面算占比用);然后 tag + 整条栈逐帧入账;
- 全程零内存分配、零写屏障(
//go:nowritebarrierrec,附录 B.3),写完立刻归还信号处理器身份。
第 5 步:无限循环第 2~4 步。 你的程序该干嘛干嘛,对这一切毫无感知;每 10ms 一笔,默默累积。
第 6 步:收工。 pprof.StopCPUProfile() → SetCPUProfileRate(0) 拆闹钟 → addExtra 在账本里补一条 EOF(告诉抄账员"没有新账了")→ 抄账员把最后的存账抄完、编码、flush 到文件 → <-done 等它干完 → 函数返回。账本清空(log=nil),第二层防重入解除,下次还能再开。
这就是全部机制。剩下的两个问题:凭什么这些随机抽查能代表整体?和账本和抄账员之间没出乱子吗?。
抽查凭什么能代表整体:采样的数学直觉
直觉:时间尺度差三个数量级,抽查 ≈ 随机
疑虑很自然:每 10ms 才看一眼,一个函数从头到尾可能几微秒就跑完了,凭什么"看到的占比"等于"真实的耗时占比"?
答案的关键在于两个时间尺度差了三个数量级:采样间隔 10ms,函数单次执行微秒级。程序 1 秒内换过几百万次"正在执行哪个函数",而采样只看 100 眼——每一眼落在哪里,对程序而言近似随机(闹钟由内核定时器驱动,和你的代码节奏毫无关联)。于是:
一个函数占 CPU 时间 30%,就意味着时间轴上 30% 的位置它在跑,随机撒 100 个采样点,平均就会有 30 个落在它头上。
占比是"时间轴上的覆盖比例",采样点是"撒在时间轴上的探针"——探针落进哪个区间,就给哪个区间记一票。样本越多,票数比例越贴近覆盖比例(大数定律),误差大约按 1/√N 收缩:100 个样本误差 ±5 个百分点上下,300 个 ±3,1000 个 ±2。这就是剖析报告里所有百分比的来源,没有别的魔法。
下面三个实验,用真实 pprof 验证"线性""比例""只算 CPU 时间"三个性质。
动手实验1:采样量与 CPU 时间成正比
模块准备:
mkdir apx-lab && cd apx-lab # 已存在就 cd 进去
go mod init apx-lab # 已有 go.mod 就跳过
cpu1/main.go(完整可复制):
package main
import (
"os"
"runtime/pprof"
"strconv"
"time"
)
var sink int // 防止忙循环被编译器优化掉
func busy(ms int) {
deadline := time.Now().Add(time.Duration(ms) * time.Millisecond)
x := 0
for time.Now().Before(deadline) {
for i := 0; i < 100000; i++ {
x += i
}
}
sink += x
}
func main() {
ms, _ := strconv.Atoi(os.Args[1])
f, _ := os.Create("cpu.pprof")
pprof.StartCPUProfile(f)
busy(ms) // 期间每 10ms 被 add() 记一笔
pprof.StopCPUProfile()
f.Close()
}
go run ./cpu1 1000 && go tool pprof -top cpu.pprof | grep -E "Total samples|busy"
go run ./cpu1 2000 && go tool pprof -top cpu.pprof | grep -E "Total samples|busy"
go run ./cpu1 4000 && go tool pprof -top cpu.pprof | grep -E "Total samples|busy"
实测输出(go1.24.0 / Windows 11):
Duration: 1.14s, Total samples = 1000ms (87.52%)
970ms 97.00% 97.00% 970ms 97.00% main.busy
Duration: 2.14s, Total samples = 2s (93.39%)
1.94s 97.00% 97.00% 1.95s 97.50% main.busy
Duration: 4.15s, Total samples = 3.96s (95.44%)
3.91s 98.74% 98.74% 3.93s 99.24% main.busy
解读:CPU 时间翻倍,采样毫秒数精确跟着翻倍(1000 → 2000 → 3960ms)。Total samples 就是账本里样本笔数的总和 × 10ms——剖析文件不存"秒",只存"多少笔、每笔几毫秒"(还记得 A.1 第 4 步里 add 记的第一条元数据 hz=100 吗?每笔 = 1000ms/100 = 10ms,pprof 读报告时用 hz 把笔数换算回时间)。那 ~3% 的差额是起停间隙和打断本身的开销。
动手实验2:两个函数的占比 ≈ 时间比
cpu2/main.go(完整可复制,脚手架 sink 同上):
package main
import (
"os"
"runtime/pprof"
"time"
)
var sink int
// parse 和 compute 是两个独立函数(各烧各的 CPU),时间比 1:2
func parse(ms int) {
deadline := time.Now().Add(time.Duration(ms) * time.Millisecond)
for time.Now().Before(deadline) {
for i := 0; i < 100000; i++ {
sink += i
}
}
}
func compute(ms int) {
deadline := time.Now().Add(time.Duration(ms) * time.Millisecond)
x := 0
for time.Now().Before(deadline) {
for i := 0; i < 100000; i++ {
x += i * i
}
}
sink += x
}
func main() {
f, _ := os.Create("cpu.pprof")
pprof.StartCPUProfile(f)
parse(300) // 计划烧 300ms
compute(600) // 计划烧 600ms
pprof.StopCPUProfile()
f.Close()
}
go run ./cpu2 && go tool pprof -top cpu.pprof | grep -E "Total samples|parse|compute"
实测输出(go1.24.0 / Windows 11):
Duration: 1.04s, Total samples = 900ms (86.92%)
580ms 64.44% 64.44% 580ms 64.44% main.compute
280ms 31.11% 95.56% 290ms 32.22% main.parse
解读:计划 1:2(300ms:600ms),抽样给出 280:580 ≈ 1:2.07。抽样从不知道"计划",它只是每 10ms 看一眼——两个函数对时间轴的覆盖比例,被 90 个采样点忠实地投票出来了。误差(300→280)正是 1/√N 量级的统计涨落。
动手实验3:睡觉不计账——CPU 时间 ≠ 挂钟时间
cpu3/main.go(完整可复制):
package main
import (
"os"
"runtime/pprof"
"time"
)
var sink int
func busy(ms int) {
deadline := time.Now().Add(time.Duration(ms) * time.Millisecond)
x := 0
for time.Now().Before(deadline) {
for i := 0; i < 100000; i++ {
x += i
}
}
sink += x
}
func main() {
f, _ := os.Create("cpu.pprof")
pprof.StartCPUProfile(f)
busy(300) // 烧 CPU:会计账
time.Sleep(300 * time.Millisecond) // 睡觉:不会计账
pprof.StopCPUProfile()
f.Close()
}
go run ./cpu3 && go tool pprof -top cpu.pprof | grep -E "Duration|busy"
实测输出(go1.24.0 / Windows 11):
Duration: 600.84ms, Total samples = 310ms (51.59%)
270ms 87.10% 87.10% 280ms 90.32% main.busy
解读:Duration(挂钟)601ms,Total samples(CPU 账)只有 310ms——睡觉那 300ms一笔都没有。原因回到 A.1 第 2 步:打断落在"正在跑的代码"头上;睡觉的 goroutine 不在任何核上跑,自然没人被拍肩。CPU 剖析账本里记的是"谁在烧 CPU",不是"谁在耗时"——这就是为什么 I/O 等待型瓶颈在 CPU 剖析里隐形,得去查阻塞剖析或 trace(后篇的主题)。
反面教材:抽查也会生病(混叠)
前三个实验是真实 pprof;最后一个实验把整套机制缩小成玩具,让你同时看见"抽查"和"钟表真相"两本账,亲眼确认它们对得上——也亲眼看看它们什么时候会对不上。
动手实验4:抽样模拟器——抽查 vs 钟表,与"混叠"病
sim/main.go(完整可复制):一个工人在 parse/compute/write 三个工位循环干活(工时单位 2:5:3),闹钟每 10ms 抓拍一眼工位记一笔(= 抽样);同时用钟表实测各工位真实耗时(= 真相),最后两本账对表:
package main
import (
"fmt"
"math/rand"
"sync/atomic"
"time"
)
// 模拟 CPU 剖析的两个角色:
// worker = 被打断的"工人":在 parse/compute/write 三个工位循环干活,时间比 2:5:3
// ticker = "闹钟+记录员":每 10ms 抓拍一眼工人当前工位,记一笔账
// 另有真实钟表同步测量各工位实际耗时——抽样占比 vs 真实占比,两相对照。
var where atomic.Int32 // 工人此刻在哪个工位(0=换位中 1=parse 2=compute 3=write)
var sink int // 防优化
func work(units int) { // 一个 unit ≈ 等量 CPU 时间
x := 0
for i := 0; i < units*1000; i++ {
x += i
}
sink += x
}
func main() {
const hz = 100
names := map[int32]string{0: "换位(调度)", 1: "parse ", 2: "compute ", 3: "write "}
hist := map[int32]int{}
var real [4]atomic.Int64 // 各工位真实耗时(纳秒),由钟表测出
go func() { // 工人:时间比 2:5:3;每圈再随机磨蹭几下
for {
t := time.Now()
where.Store(1)
work(2)
real[1].Add(int64(time.Since(t)))
t = time.Now()
where.Store(2)
work(5)
real[2].Add(int64(time.Since(t)))
t = time.Now()
where.Store(3)
work(3)
real[3].Add(int64(time.Since(t)))
t = time.Now()
where.Store(0)
work(rand.Intn(2)) // 抖动:打破"工人周期与闹钟成整数比"的混叠
real[0].Add(int64(time.Since(t)))
}
}()
deadline := time.Now().Add(3 * time.Second)
tick := time.NewTicker(time.Second / hz)
for range tick.C { // 闹钟每 10ms 响一次 = 一次"拍肩"
hist[where.Load()]++ // 记录员的全部工作:看一眼现场,记一笔
if time.Now().After(deadline) {
tick.Stop()
break
}
}
var totalS int
var totalR int64
for i := 0; i < 4; i++ {
totalS += hist[int32(i)]
totalR += real[i].Load()
}
fmt.Println("工位 抽样占比 真实(钟表)占比 抽样笔数")
for _, k := range []int32{1, 2, 3, 0} {
fmt.Printf(" %s %5.1f%% %5.1f%% %d\n",
names[k],
100*float64(hist[k])/float64(totalS),
100*float64(real[k].Load())/float64(totalR),
hist[k])
}
fmt.Println("共", totalS, "笔抽样 / 3 秒 @", hz, "Hz")
}
go run ./sim
实测输出(go1.24.0 / Windows 11):
工位 抽样占比 真实(钟表)占比 抽样笔数
parse 24.3% 25.5% 73
compute 34.7% 32.2% 104
write 37.7% 38.6% 113
换位(调度) 3.3% 3.7% 10
共 300 笔抽样 / 3 秒 @ 100 Hz
解读:
- 两本账对上了:每一行的抽样占比与钟表占比都咬合在 ±2.5 个百分点内——300 笔抽样(真值 25/32/39),正好是
1/√N预告的误差量级。这就是 A.2 开头那句"覆盖比例 vs 探针投票"的实证。 - 真实占比不等于工时单位之比 2:5:3(20/50/30):钟表实测的 parse/write 每单位机器耗时比 compute 高(循环机器码对齐等微观因素)。真相以钟表为准——抽样估的就是钟表占比,而不是"计划配比",这个坑正好演示了"占比的真实含义"。
- 混叠病,以及怎么得的:这个模拟器的早期版本没有"换位磨蹭"那个随机抖动工位时,工人节奏与闹钟 10ms 成整数比,抓拍每次落在循环同一相位,实测抽样给出 17.3 / 42.3 / 40.3——偏差拉到 ±8 个百分点。这病叫混叠(aliasing):抽样成立的前提"采样点近似随机"被整数比对齐破坏了。加上随机抖动后偏差立刻缩回 ±2.5。真实 cpuprof 几乎不犯这病——内核定时器和用户代码不同源,拍子对不上。
账本与抄账员:样本去哪了,丢了怎么办
②每 10ms 记一笔,④每 100ms 才醒来一次——记账速度是抄账的 10 倍,中间全靠账本③(profbuf)兜着。这段关系三个要点:
要点一:账本是无锁的,靠"各写各的计数器"。 记账员绝不等待(铁律),抄账员也从不和记账员抢格子——一个只推进"写了多少",一个只推进"抄了多少",一本书两个书签,谁也不用问谁。这是并发编程里很漂亮的一招,叫单写单读(SPSC)环形缓冲,完整拆解 + 可运行实验在附录 B.4(实测:读者跟得上时 3 秒 300 笔零丢失)。
要点二:账本满了就撕,撕的笔数会入账。 万一抄账员太慢(比如 GC 把它饿着了),账本写满后记账员的唯一选择是丢笔并给"溢出计数"+1——宁可报告缺一笔,不能流水线卡一毫秒。溢出最终变成剖析报告里的"丢失样本"记录。附录 B.4 的慢读者实验实测:写 300 笔、抄走 120 笔、撕掉 116 笔,数字严丝合缝(116+184=300)。
要点三:抄账员的收工仪式,就是 §八的 readProfile。 profileWriter 每 100ms 醒来调一次 readProfile:
signalLock置真——记账员这下 CAS 拿不到锁,新样本自动放弃(不是等待!)。这就是那把锁的全部用途:抄账时短暂冻结记账,而不是排队;- 把账本里的存账整批抄走;
- 若已经收到 EOF(StopCPUProfile 补的),做销账动作:
cpuprof.log = nil——账本作废,整个剖析周期正式结束,StartCPUProfile可以开下一轮了。
两层防重入到这里就齐了:开工时
StartCPUProfile检查"已开着"标志(第一层,防你开两次);收工时log=nil(第二层,保证下一轮从干净状态开始)。03 篇实验六演示的"连开两轮 Start/Stop + 调runtime.CPUProfile()panic",演的就是这两层的接力。
往账本里夹纸条:标签(tag)是什么
一笔账 = 一条调用栈。但有时你想多记一笔"这笔账属于哪条业务线"——比如同一个 sync.Mutex.Lock,想区分是路由 A 还是路由 B 撞上的。这就是标签(pprof labels):
pprof.Do(ctx, pprof.Labels("route", "sync"), func(ctx){...})——进入这段代码前,把route=sync这张纸条挂到当前 goroutine 身上;- 被拍肩时,
add()连纸条一起入账(tagPtr 指针,见 03 篇 §九); - 分析时按纸条分组:
go tool pprof -tagfocus=route=sync cpu.pprof,只看这条业务线的账。
白话:标签就是给每笔账夹的一张分类纸条,记账时多抄一眼挂在 goroutine 身上的纸条而已,机制零新增。完整可跑实验在 03 篇 §九(动手实验七:labels + tagfocus,实测按标签过滤前后占比变化),此处不重复。