perf:CPU 到底在干什么,只有采样能回答

难度 ★★★★★ · 前置:eBPF:为什么它能把观测成本降到几乎为零 | 一句话结论:perf 靠硬件性能计数器定时中断采样,每次中断记下「当前在哪个函数、调用栈是什么」。它采样的是 CPU 时间——所以它对「CPU 忙但慢」有效,对「CPU 闲着但慢」完全无效,那时候你需要的是 eBPF。

那台 load 48、CPU 却闲着的机器

告警说一台 32 核机器的 load average 冲到 48,我登上去,手已经在敲 perf record 了,被旁边的同事按住,他说先看 top。(他后来成了我组长,按我那一下是我入职头一年学到的最便宜的一课,比后面所有排查加起来都值钱。)

1
top -b -n1 | head -15
1
2
3
top - 14:22:31 up 41 days,  3:12,  2 users,  load average: 48.21, 46.88, 44.02
%Cpu(s): 3.1 us, 1.2 sy, 0.0 ni, 92.4 id, 3.2 wa, 0.0 hi, 0.1 si, 0.0 st
MiB Mem : 64321.0 total, 1204.5 free, 31022.3 used, 32094.2 buff/cache

48 除以 32 差不多一点五,我当时的想法很直接,肯定有东西在烧 CPU,可那一行 %Cpu(s) 就摆在那里,92.4% 的空闲,wa 只有 3.2%,机器明明闲得发慌,load 却高得像马上要炸,这两个数字放在一起,本身就是答案的一半。我在别的机器上见过 load 五十几的样子,那时候风扇是真的在转,机箱摸上去烫手,us 那一栏能顶到九十往上,而这台机器安安静静,连风都不怎么出,两种局面摆在一起对比,你很难相信它们是同一个指标报出来的。

这台机器没有 CPU 问题,第一反应就不该是采样。

load average 在 Linux 上算的是 TASK_RUNNING 加 TASK_UNINTERRUPTIBLE,也就是在跑加在等 IO 且不可中断,wa 只有 3.2% 而 load 是 48,说明大量进程卡在 D 状态,而 iostat 可能连磁盘利用率都不高,它们等的不是盘,是网络,是某个已经半死不活的挂载点。这个指标的名字起得特别坑人,load 听起来像负载,实际统计的是排队人数,一个在等文件句柄的进程和一个在满核跑运算的进程,对 load 的贡献完全一样。更麻烦的是 D 状态的进程连 kill -9 都不理你,因为信号要等系统调用返回才会被处理,它卡在那个系统调用里出不来,你能做的只有等或者把挂载点从下面换掉。

第一步该干的是看谁在等。

1
ps -eo pid,stat,wchan:24,comm | awk '$2 ~ /^D/'
1
2
4210 D    nfs_wait_bit_killable  python3
4231 D nfs_wait_bit_killable python3

两条记录,wchan 全是 NFS,挂载点响应慢,所有碰它的进程就都在 D 里排队,和 CPU 没有关系。

如果这时候真跑了 perf,它会告诉我 CPU 很闲,这个答案没错,只是答非所问,我要的明明是谁在拖住那 48 个进程,它回答的却是谁在吃我的核。这两件事看起来都叫性能问题,实际上分属两个完全不同的诊断分支,一个问的是资源够不够用,一个问的是资源在等谁,前者用采样,后者用排队信息。我入职头一年最大的收获就是学会了先分辨自己在哪个分支上,因为一旦问错了问题,工具越强,你被带偏得越快,perf 那屏干干净净的数据就是最好的例子,它甚至会让你觉得机器没问题。perf 什么时候该用、什么时候不该用,比 perf 怎么用还要先搞清楚。

它数的是周期,不是函数调用

perf record 默认采 cycles 事件,CPU 每执行 N 个周期触发一次中断。

1
CPU 执行指令 → 周期计数器到阈值 → PMU 中断 → 内核记录 IP + 调用栈 → 继续执行

关键在这里,采样是按 CPU 周期或者按时间来的,不是按函数调用来的,所以 perf 报出来的百分比,意思是这一堆采样点里有多少个落在这个函数上,换个说法就是这个函数吃掉了多少 CPU 时间,它描述的是时间分布,不是执行次数。一个每毫秒调一次但只跑十微秒的函数,和一个每秒调一次却跑满一毫秒的函数,在采样里能给出完全一样的高度,可你要做的优化动作截然不同,前者该想办法降低调用频率或者下移到用户态,后者该去改它的实现。

也正因为如此,它天生只对 CPU 忙但慢有感,CPU 闲着的时候,没有采样点会落在任何人身上,采出来是一片空白,而那片空白经常被误读成没有问题,我见过不止一个人拿着这样的图说代码已经没有优化空间了,实际上他测的那段时间里进程压根没在跑,全在等锁或者等 IO。(我第一年就吃过这个亏,图上一片干净,我一度以为是自己采样时间太短,还特意把 -F 从 99 调到 999 又跑了一遍,结果还是干净的,后来才想明白根本没有东西可采。)

这条性质决定了后面所有的用法和所有的误用,你要先承认它只能看见 CPU 时间,再谈它准不准。

三种事件,和一台没有 PMU 的虚拟机

类别 事件 需要什么
硬件 cycles、instructions、cache-misses、branch-misses CPU 的 PMU(几乎都有)
软件 task-clock、context-switches、page-faults、cpu-migrations 只要有内核
tracepoint sched:sched_switch、syscalls:sys_enter_openat 内核预埋的静态点

task-clock 是按 CPU 时间采样,比 cycles 省事,不依赖 PMU,虚拟机里也能用。

1
perf record -e task-clock -g ./app

虚拟机里经常没有 PMU,这时候你让 perf 去数 cycles,它会直接甩一行报错给你,连数据都不采。

1
perf: Not counting hardware events, cannot access kernel perf_event.

办法就是换 task-clock,不用纠结,也别去折腾什么内核参数,宿主机不给你,你在客机里怎么调都没用。我第一次在云主机上撞见这个报错时还以为是自己权限不够,加了 sudo 依然不行,查了半天才明白是虚拟化层压根没把 PMU 透传下来,而云厂商的文档里只在某页最底下用一行小字写着这件事。这件事教给我的东西比那个报错本身重要得多,在云上,你的机器下面还压着一层你看不见的虚拟化,很多被你当成内核行为的东西,其实是宿主机替你决定的,你能做的只是换一条不依赖它的路,然后继续往下排查。

五个子命令,真正排查只用 record

命令 用途 采样范围
perf top 实时看全系统热点 整个系统
perf stat 看总数(指令/周期/缓存未命中率) 一条命令或一个 PID
perf record 采样并保存 可指定
perf report 分析保存的数据 离线
perf trace 类似 strace 但开销低一点 系统调用

perf top 的定位是先看看有没有问题,perf record 的定位是有问题了要定位,两个工具解决的是两种处境,前者靠眼睛,后者靠数据。

perf top 不能事后分析,perf record 存下来能反复看,真排查问题的时候永远用 record,因为你永远不知道问题什么时候复现,而 top 只在它复现的那几秒里有用,错过了就是错过了。这一点我吃过实在的亏,有次线上抖动是半小时一次的,我开了 top 盯着屏幕看了二十分钟,脖子都僵了,那次抖动还是没赶上下一次,最后老老实实挂上 record 采了一个钟头才抓到现场。

为什么是 99 次,不是 100 次

1
perf record -F 99 ...

-F 99 是每秒采样 99 次。

为什么不取 100,因为 100 正好等于内核的调度 tick(CONFIG_HZ=100 的老机器,或者 250/1000 的整除数),采样点和 tick 处理锁相之后,就只覆盖 tick 附近那段代码。99 是质数,周期是 10.101ms,和任何常见的整毫秒周期都错开,长期下来采样点会扫过代码的每一段。这个说法在 Brendan Gregg 的文章里能查到,他跟 Peter Zijlstra 讨论过。

每个采样点要做四件事,这四件事跟采样频率是线性关系,频率翻十倍,开销也差不多翻十倍。

  1. 触发 PMU 中断;
  2. 保存寄存器;
  3. 展开调用栈(最贵的一步,带 -g 时要读栈内存);
  4. 写入 ring buffer。

-F 999 加上 -g,开销可能到 10% 以上,-F 99 通常在 1% 以下,差了整整一个数量级,而这两档给出的热点排序在多数场景里几乎没有区别。至于不指定 -F 会怎样,perf 不设默认采样频率,它采 cycles 事件并按内核的 perf_event_max_sample_rate 封顶(默认 100000,且会按开销自适应下调),所以想看准数,还是显式写 -F 99 -g。

从采样点到一张火焰图

五步。中间两步是 Perl 脚本,来自 Brendan Gregg 的 FlameGraph 仓库。

没有火焰图的话,perf report 给出的调用栈是平铺的,看不出谁占了最多时间。

火焰图怎么读。

  • 横轴不是时间,是采样点数量(宽度就是占比);
  • 纵轴是调用栈深度,从下往上;
  • 找最宽的平顶,那才是热点;
  • 顺着平顶下面的调用链看,判断责任归谁。

最常见的误读是看到顶层的 __libc_start_main 很宽就以为有问题,它宽只是因为它是所有 main 函数的根,它下面挂着的每一行才是真正的答案。我第一次画出来的图里最宽的那块就是它,当时还挺得意,觉得自己找到了一个大热点,后来被同事一句你自己写的 main 也算热点吗问得没话说。从那以后我看图都从平顶往下数三层再开口,先确认这块宽度是业务逻辑烧出来的,还是启动阶段那些一次性的初始化撑起来的,两者的优化价值差着好几个数量级。

report 默认那一屏看不出东西

1
perf report

默认按符号聚合,给出的是每个符号占了多少百分比,一屏能看完,但它也到此为止了。

1
2
3
32.14%  myserver  myserver           [.] parse_json
18.02% myserver libc-2.31.so [.] __memmove_avx_unaligned_erms
11.55% myserver [kernel.kallsyms] [k] copy_user_enhanced_fast_string

它告诉我哪些函数热,不告诉我它们怎么被调用的,而绝大多数时候这个缺失的部分才是问题本身。

加上 --call-graph。

1
perf report --call-graph=graph,0.5,caller

caller 和 callee 的差别在这里很要紧。

方向 含义 用途
callee(默认) 从热点往下展开 看这个函数里时间花在哪
caller 从热点往上展开 看谁调用了这个热点

定位谁在浪费 CPU 要用 caller,热点函数本身通常没错,比如 memcpy,错的是调用它的人,你盯着 memcpy 看一整天也看不出任何东西,因为它自己的代码只有几行十几个 intrin。

[unknown] 背后基本只有一种情况:符号没了

四种原因,按出现频率排。

原因 症状 解决
没有 debuginfo [.] 0x0000a1b2 装 -dbgsym 包
符号被 strip 了 函数名显示为 [.] foo 但没有行号 编译时保留 -g(不 strip)
JIT 代码(Java/Node/V8) 一大片 [unknown] 用 perf-java 或 JVM 的 perf map
内核符号受限 [kernel.kallsyms] 全是地址 perf record 用 root,或调 kptr_restrict

第一种最常见。装 debuginfo。

(我们内网的镜像里一直没同步 ddebs 源,第一次装的时候 apt 甩了半屏 404 给我,我还以为是包名写错了,查了很久才明白是源里压根没有,最后是找运维开的权限。)

1
2
3
4
5
6
# Debian/Ubuntu
sudo apt install linux-image-$(uname -r)-dbgsym # 需要 ddebs 源
sudo apt install libc6-dbg

# RHEL/CentOS
sudo debuginfo-install glibc

装不了的话(容器里很常见),退一步用 --symfs 指向本机的符号目录。

JIT 那一种要单独处理,JVM 加 -XX:+PreserveFramePointer,或者用 perf-map-agent 生成 /tmp/perf-<pid>.map。(我第一次在 Java 服务上看到满屏 [unknown] 时,真心以为是 perf 不支持 Java,其实是 JVM 自己把栈烧掉了。)

stat 回答的是另一类问题

perf record 回答哪里慢,perf stat 回答效率高不高。

1
perf stat -e cycles,instructions,cache-misses,branch-misses ./app
1
2
3
4
4,821,392,104      cycles                      #    3.201 GHz
6,120,338,271 instructions # 1.27 insn per cycle
142,031,882 cache-misses # 2.947 % of all cache refs
18,203,947 branch-misses # 0.512 % of all branches

三个数最有价值。

指标 含义 健康值
IPC(instructions / cycles) 每周期执行几条指令 > 1.5 好,< 0.8 说明在等内存
cache-miss 率 缓存未命中比例 < 3% 正常,> 10% 说明数据局部性差
branch-miss 率 分支预测失败比例 < 1% 正常,> 5% 说明分支不可预测

IPC 掉到 0.8 以下是 CPU 在等内存的强信号,这个时候加 CPU 没有用,要动的是数据结构的布局。

这就是 stat 和 record 的根本区别,前者告诉你效率,后者告诉你位置,一个回答为什么慢,一个回答慢在哪,两个问题的答案经常对不上,而对不上的时候通常说明你问错了。

动手前先确认有没有 PMU

1
perf stat -e cycles true

成功是这样,只跑一个 true,也照样有计数出来,说明这台机器的 PMU 能访问。

1
2
Performance counter stats for 'true':
1,234,567 cycles

失败是这样,一行 Access to performance monitoring 就把路堵死了,不用往下试了。

1
Error: Access to performance monitoring and observability operations is limited.

失败就换 task-clock。

1
perf stat -e task-clock true

这一步花不了十秒,但能省掉后面半小时的为什么全是零。

perf top 的几个键,和它的局限

1
sudo perf top -F 99

交互键位。

键 作用
E 多个计数器同时采样时,切换当前显示哪一个事件
z 开关每次刷新把计数清零
d 调整刷新间隔
e 调整显示条目数
f 按命中次数过滤
K 隐藏内核符号
U 隐藏用户符号
s 注释当前符号
q 退出

这张表就是 perf top 自己打印的 INTERACTIVE PROMPTING KEYS,-g 不是交互键,它是命令行选项,要调用图就在启动时加 -g,而 / 是进到符号浏览界面之后才有的按符号名过滤,在这儿按键不管用。

perf top 的局限是它只显示当前时刻,错过就没了,偶发问题必须用 record。我一开始很喜欢 top,因为它一屏就能看出谁是热点,后来发现它看的是我盯着的那几分钟,赶上一次抖动才有用,赶不上就什么都没有,这种靠运气的工具,用在事后复盘上基本等于没用。它真正的位置是巡检,早上泡杯茶看一眼这台机器总体上谁在吃 CPU,看完就该关掉,剩下的活全归 record 和火焰图,我现在的习惯是 top 不超过三十秒,超过就说明我该采样了。

采三十秒,出一张图

1
2
3
4
5
6
7
8
9
10
# 1. 采样 30 秒(myserver 是示例进程名,换成你自己的;也可以直接写 -p <pid>)
sudo perf record -F 99 -g -p $(pgrep -o myserver) -- sleep 30

# 2. 看基本信息
perf report --stdio --sort comm,dso | head -30

# 3. 生成火焰图
git clone --depth 1 https://github.com/brendangregg/FlameGraph
perf script | ./FlameGraph/stackcollapse-perf.pl > out.folded
./FlameGraph/flamegraph.pl out.folded > flame.svg

打开 flame.svg,找最宽的平顶。

perf script 默认输出到 stdout,管道直接接 stackcollapse-perf.pl 就行,不用先落个文件。

采一个进程还是采整台机器,是另一个选择。

1
2
3
4
5
# 只采一个进程(推荐,噪声小;4210 是我那台的进程号,换成你自己的)
sudo perf record -F 99 -g -p 4210 -- sleep 30

# 采整个系统(噪声大,但能发现「谁在偷 CPU」)
sudo perf record -F 99 -g -a -- sleep 30

-a 是 --all-cpus,会记录所有 CPU,机器 CPU 高但不知道是谁的时候用它。

用 -p 的时候,perf 只跟这个进程,如果它 fork 出子进程,需要 --inherit,这个是默认开着的,但你要是显式传了 --no-inherit 就会漏掉整棵子进程树,这种坑排查起来特别费劲,因为主进程看着一切正常。

用 trace 代替 strace

1
sudo perf trace -p 4210

输出格式跟 strace 很像,开销低得多,strace 走 ptrace,每次系统调用要两次上下文切换,perf trace 走 tracepoint,代价小到可以在生产上开着跑一会儿。

默认显示全部系统调用,想只看慢的,加 --duration。

1
sudo perf trace --duration 1000 -p 4210

--duration 1000 的单位是毫秒,意思是只显示耗时超过 1000 毫秒也就是 1 秒的系统调用。

生产上要找出慢系统调用,这是最快的一条路。

谁在等锁

1
2
sudo perf lock record -- sleep 10
sudo perf lock report
1
2
  Name   acquired  contended  avg wait (ns)
&sb->s_type->i_mutex_key 18234 421 18203

contended 是争用次数,avg wait 是平均等待时间。

perf lock 需要 CONFIG_LOCK_STAT=y,很多发行版默认是关的,先查一下。

1
grep CONFIG_LOCK_STAT /boot/config-$(uname -r)

没开的话这条命令会安静地给你一张空表,比报错更容易让人误解,你会以为自己这台机器上根本没有锁竞争,其实只是没统计。

缺页、上下文切换、跨核迁移

1
perf stat -e page-faults,context-switches,cpu-migrations ./app
事件 高说明什么
page-faults 内存分配多 / 栈太小 / 内存不足
context-switches 锁竞争 / 阻塞 IO 多
cpu-migrations 线程在核之间跳,影响缓存命中

cpu-migrations 高是性能莫名地差的常见原因,线程每换一次核都要重新填 L1/L2,而重新填的成本取决于你的工作集有多大,工作集一旦超过 L2,每跳一次就是一次冷启动。用 taskset 绑核能把它消掉。

1
taskset -c 0-3 ./app

时间花在内核还是用户态

1
perf report --sort dso

会看到这样的分布。

1
2
3
58.21%  libc-2.31.so
22.14% [kernel.kallsyms]
19.65% myserver

内核态占 22% 偏高,可能的原因有系统调用多、内存分配多,或者锁竞争。

再往下看具体是哪些内核函数。

1
perf report --sort dso,symbol | grep -A5 kallsyms   # 想按内核函数摊开,用 perf report -i perf.data --sort symbol

加 CPU 也不涨 QPS 的时候

1
2
perf stat -e cycles,instructions,cache-references,cache-misses \
-e LLC-loads,LLC-load-misses ./app

LLC-load-misses / LLC-loads 超过 20%,说明最后一级缓存的命中率差,这时候要改的是数据结构的布局,比如把热数据集中放,避免指针追逐。这是加 CPU 也不涨 QPS 最典型的原因,加核解决的是并行度,而局部性问题是加多少核都治不好的病,核越多,每个核抢到的 cache 越少,有时候还会更慢。我做过一次这样的优化,把一个遍历链表的热点改成把相邻节点的字段拆到两个连续数组里,代码看起来啰嗦了一倍,QPS 涨了四成,同一次压测里 LLC-load-misses 从 31% 掉到 9%,其他什么参数都没动。

栈不完整的时候

1
perf record -F 99 --call-graph dwarf,8192 ./app

默认的 fp 模式依赖 frame pointer,编译要带 -fno-omit-frame-pointer,现代编译器默认会省略它,栈就不完整了。

dwarf,8192 用调试信息展开栈,8192 是栈大小的上限,更准,但开销更大,因为要读更多内存。

折中的办法是编译时加上 -fno-omit-frame-pointer,继续用 fp,多占一个寄存器换一份能读的栈,这笔交易在排查阶段永远划算。

复现一次有符号却只看到地址

1
2
3
4
# 先 strip 掉符号
strip --strip-all ./app
sudo perf record -F 99 -g ./app -- sleep 2
perf report --stdio | head -10

会看到大量 [.] 0x0000a1b2,这就是没有符号的现场。

恢复办法是留一份带符号的二进制。

1
2
3
cp app app.debug
strip app
sudo perf record --symfs=. -F 99 -g ./app -- sleep 2

--symfs 指向包含 app.debug 的目录,perf 会拿它来解符号。

我自己先搞错的几件事

load average 高就要看 perf,这条错得最离谱。load 高而 CPU 低,说明大量进程在 D 状态等 IO,先去 ps 看 wchan,去看 iostat,perf 在这里帮不上忙,硬跑一遍只会得到一句 CPU 很闲,然后让你更困惑。

perf top 里某个函数占比高就是它慢,占比高只说明它吃的 CPU 多,一个每次调用 1 微秒、每秒被调一百万次的函数,和一个每次 1 秒、每秒调一次的,在 perf 里的占比可以一样,但优化的方向完全相反,一个该改算法,一个该改调用频率。想分清这两种,光看占比不够,还得看调用次数,perf stat -e instructions,cycles 配一段固定负载能算出平均值,或者干脆用 eBPF 数调用次数,两条路都比盯着火焰图猜强。

perf record 会影响性能所以不能上生产,-F 99 的开销通常在 1% 以下,真正不能上生产的是 strace。我第一次在线上开 perf record 之前请示了三个人,结果采完一看,业务指标连个毛刺都没有。

[unknown] 是 perf 的 bug,通常是符号缺失。装 debuginfo、保留一份带符号的二进制、编译加 -fno-omit-frame-pointer,能解决绝大部分,剩下那些基本都在 JIT 和内核符号权限上。

perf stat 和 perf record 差不多,完全不同。stat 给总数和效率(IPC、缓存率),record 给采样点和调用栈(位置),一个是体检报告,一个是 CT 片。

IPC 越高越好,这句也不对。IPC 只是每周期执行多少条指令,一条指令慢但有用(比如 AVX512 一次算 16 个浮点),IPC 低而吞吐高,它是诊断工具,不是评分标准,把 IPC 当 KPI 会逼着人去写一堆看起来聪明实际更慢的代码。我见过一次争论,两个人为了谁的服务更优在群里比 IPC,一个 1.8 一个 1.2,可那个 1.2 的每秒钟处理的请求数是对方的两倍,赢的那个最后没说话,因为再往下问就得解释他为什么用了一半的 CPU 干了人家一半的活。

采得越久数据越准,采样有时间窗口,采 30 秒能覆盖一次 GC 周期,采 3 小时能覆盖一次批处理,取决于你在找什么问题。你要是拿 30 秒的图去解释一个每天凌晨两点才跑一次的定时任务,那图上当然什么都没有。反过来说,也不是越久越好,采上一个通宵的 perf.data 动辄几个 G,perf report 打开要等好几分钟,翻页还卡,真有这么长的需求,用 perf record -D 分片或者干脆改成 eBPF 只记关键事件,效率会高得多。

perf 能替代 eBPF,不能。perf 按时间采样 CPU,eBPF 按事件执行,需要每次 read 调用都记一笔这种需求,perf 做不到,采样会漏,必须用 eBPF。

回到开头那台机器

  • perf 靠硬件性能计数器定时中断采样,记录 IP 和调用栈。它采样的是 CPU 时间。
  • load 高而 CPU 低的时候别用 perf,那是 D 状态的问题,去看 ps -eo stat,wchan。
  • -F 99 是避开共振加控制开销的默认选择,-g 展开调用栈是开销最大的一步。
  • 只有 caller 方向能回答谁调用了这个热点,定位问题用 --call-graph=graph,0.5,caller。
  • 火焰图横轴是采样占比不是时间,找最宽的平顶,别被 __libc_start_main 骗了。
  • perf stat 看效率:IPC 掉到 0.8 以下说明在等内存,LLC miss 超过 20% 说明数据局部性差。
  • [unknown] 八成是符号缺失,不是 perf 的 bug。
  • 虚拟机里没有 PMU 就用 -e task-clock。
  • perf 和 eBPF 互补:一个按时间采样回答 CPU 花在哪,一个按事件触发回答谁在什么时候做了什么。

那台机器最后确认是 NFS 那一侧的事,跟 CPU 没有关系,但那天留下的习惯一直在,先判断这是不是 CPU 的问题,再去摸 perf。

写到这里,这个专栏也就收尾了,从 Linux 是什么到怎么看见内核在做什么,中间每一篇其实都在回答同一个问题,这台机器现在到底在干什么。

如果还要往下写,有三个方向可以接着走,一个是文件系统的内部,ext4 和 xfs 的块分配与日志到底怎么把一个字节放到盘上,一个是调度器,CFS 换到 EEVDF 之后实时任务怎么在一个核上分时间,还有一个是容器的底层,namespace 加 cgroup 的那套完整实现。这三个方向都不比这三十几篇轻,但方法还是同一个,先找到一个具体的问题,然后顺着系统调用往下走。