Go CPU 剖析:四角色白话机制 + 实测实验

0 阅读14分钟

目录

  • 一句话与四个角色
  • 闹钟与拍肩:一次采样的完整旅程
  • 抽查凭什么能代表整体:采样的数学直觉
  • 账本与抄账员:样本去哪了,丢了怎么办
  • 往账本里夹纸条:标签(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 制造一次打断只负责响,不管谁听到
② 工人侧 handlersigprof → cpuprof.add抓当前栈,记一笔快进快出:不睡觉、不等锁、不碰堆(见附录 B.1)
③ 账本profbuf.go攒样本,吸收速度差单写单读无锁;满了丢笔计数(见附录 B.4)
④ 抄账员profileWriter + readProfile批量取走、编码落盘普通世界,可以用锁、可以分配内存

IMG-A-roles.png

图1:内核定时器(闹钟)每 10ms 拍一次肩 → 被拍肩的工人(sigprof 抓当前调用栈)→ 环形账本(profbuf 无锁缓冲)→ 抄账员(profileWriter 编码落盘)。配合上面的 ASCII 图一起看,机制就立起来了。

为什么②这么苦大仇深? 因为它跑在信号处理器里——操作系统随时可能在任何两条指令之间叫它上岗,而被打断的代码可能正处于任何中间状态。这三条铁律(不睡觉、不等锁、不碰堆)是理解 03 篇所有源码设计的钥匙,完整论证在附录 B.1。


闹钟与拍肩:一次采样的完整旅程

把 pprof.StartCPUProfile(f) 到 pprof.StopCPUProfile() 之间发生的事,按时间顺序讲一遍。对照 03 篇的源码位置,每一步只讲"发生了什么、为什么"。

IMG-A-timeline.png

**图 **:每 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:

  1. signalLock 置真——记账员这下 CAS 拿不到锁,新样本自动放弃(不是等待!)。这就是那把锁的全部用途:抄账时短暂冻结记账,而不是排队;
  2. 把账本里的存账整批抄走;
  3. 若已经收到 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,实测按标签过滤前后占比变化),此处不重复。