3.15 内核调试、观测与性能分析

3.14 写完了驱动。但驱动加载后崩了怎么办？性能不达预期怎么办？「看代码」能解决一部分问题，剩下的大多数需要证据：函数调用顺序、参数值、耗时分布、内存布局、锁的持有关系。

内核观测的困难在于「不能随便加 printf」：加日志要重编内核、重启机器；生产环境不允许。所以内核演化出了一整套「不重编、可动态开关」的观测设施：ftrace 的函数追踪、perf 的采样、kprobe 的动态插桩、eBPF 的可编程探针。它们各自有明确的适用边界，选错工具会浪费大量时间。

本章按「工具能回答什么问题」组织，而不是按工具名罗列。母本：奔跑吧第 6 章（QEMU 调试、ftrace、SystemTap、内存检测、死锁检测）、网络第 9 章（性能优化方法论）、鸟哥第 18 章（开机与日志）。

3.15.1 观测的五个层次

  ┌─────────────────────────────────────────────────────────────┐
  │ 5. 事后分析   crash / drgn / pstore / kdump                 │  ｜ 已经崩了
  ├─────────────────────────────────────────────────────────────┤
  │ 4. 检查器     KASAN / KFENCE / lockdep / kmemleak / KCSAN    │  ｜ 提前拦截
  ├─────────────────────────────────────────────────────────────┤
  │ 3. 采样       perf record / perf stat / perf top             │  ｜ 统计热点
  ├─────────────────────────────────────────────────────────────┤
  │ 2. 动态插桩   ftrace / kprobe / uprobe / bpftrace / perf probe│  ｜ 按需取证
  ├─────────────────────────────────────────────────────────────┤
  │ 1. 静态日志   printk / dev_dbg / trace_printk / dynamic_debug│  ｜ 改代码
  └─────────────────────────────────────────────────────────────┘
       代价：从下到上「侵入性递减、信息密度递减、准备成本递增」

读图：从下往上，工具越来越「不侵入」，但越来越依赖「问题已经复现」。实际排查通常是从上往下：先看日志与指标（层次 1 的产物）、再用采样找热点（3）、需要细节时上动态插桩（2）、怀疑内存/并发 bug 时开检查器（4）、真崩了才用事后工具（5）。

3.15.2 printk 与 dynamic_debug：最朴素也最可靠

printk 是内核的 printf，但有三个额外概念：级别、缓冲区、console。

/* 级别 0–7，数字越小越严重 */
pr_emerg("...");   /* 0 */
pr_alert("...");   /* 1 */
pr_crit("...");    /* 2 */
pr_err("...");     /* 3 */
pr_warn("...");    /* 4 */
pr_notice("...");  /* 5 */
pr_info("...");    /* 6 */
pr_debug("...");   /* 7，默认不输出 */

printk 先写进环形缓冲区 log_buf，再由 console 输出。这解释了两个现象：① 早期启动的日志能在 console 就绪后「补打」；② 缓冲区满后旧日志被覆盖，dmesg 看不到完整历史（用 journalctl -k -b 或加大 log_buf_len=）。

# 当前 console 级别（四个数字：console/默认/最小/默认 console）
cat /proc/sys/kernel/printk
# 7       4       1       7

# 只让 4 级（warn）以上输出到 console
echo 4 > /proc/sys/kernel/printk

# 持续跟踪
dmesg -wT
journalctl -k -f

dynamic_debug 让 pr_debug()/dev_dbg() 在运行时按文件、函数、行号开关，不用重编：

# 打开某个文件的所有 pr_debug
echo 'file mychar.c +p' > /sys/kernel/debug/dynamic_debug/control
# 打开某个函数的
echo 'func mychar_read +p' > /sys/kernel/debug/dynamic_debug/control
# 关掉
echo 'file mychar.c -p' > /sys/kernel/debug/dynamic_debug/control
# 看当前有哪些可调点
grep -c '=_' /sys/kernel/debug/dynamic_debug/control

还可以用启动参数：dyndbg="file drivers/net/* +p"。+p 是打印，+f 是加函数名，+l 是加行号，+m 是加模块名。

新代码里，pr_fmt 可以统一加前缀：

#define pr_fmt(fmt) "mychar: " fmt
#include <linux/printk.h>
/* 之后 pr_info("open by %s\n", comm) 会输出 "mychar: open by bash" */

3.15.3 ftrace：函数级与事件级的追踪

ftrace 是内核自带的追踪框架，挂在 tracefs 上（6.x 推荐 /sys/kernel/tracing，兼容 /sys/kernel/debug/tracing）。

cd /sys/kernel/tracing
cat available_tracers
# blk function function_graph irqsoff preemptoff wakeup wakeup_rt hwlat osnoise timerlat nop

function 与 function_graph

# 只看「谁被调用了」，开销最小
echo function > current_tracer
echo 'vfs_*' > set_ftrace_filter        # 支持通配符，减少输出
echo 1 > tracing_on
cat /etc/hostname > /dev/null
echo 0 > tracing_on
cat trace | head -20

# 看调用树与耗时
echo function_graph > current_tracer
echo 'do_sys_openat2' > set_graph_function
echo 1 > tracing_on
cat /etc/hostname > /dev/null
echo 0 > tracing_on
cat trace | head -40

function_graph 的输出形如：

 1)               |  do_sys_openat2() {
 1)               |    getname_flags() {
 1)   0.512 us    |      kmem_cache_alloc();
 1)   1.234 us    |    }
 1)               |    do_filp_open() {
 1)               |      path_openat() {
 1) + 12.345 us   |        ...

左侧是 CPU 号，+/! 标记「超过阈值」，右侧是耗时（µs）。set_graph_ancestor/set_graph_function 控制追踪的根，避免输出爆炸。

事件（tracepoint）与 kprobe

# 打开一个 tracepoint
echo 1 > events/sched/sched_switch/enable
cat trace_pipe

# 用 kprobe 抓 do_sys_openat2 的参数
echo 'p:myopen do_sys_openat2 dfd=%di filename=%si flags=%dx' > kprobe_events
echo 1 > events/kprobes/myopen/enable
cat trace_pipe

# 抓返回值（kretprobe）
echo 'r:myopen_ret do_sys_openat2 ret=$retval' >> kprobe_events

kprobe_events 的语法：p[:[GRP/]EVENT] SYM[+offs] [FETCHARGS]，%di 是 x86-64 的第一个参数寄存器，$retval 是返回值，+0(%si) 可以解引用指针（+0(%si):string 按字符串读）。

trace-cmd 是 ftrace 的命令行封装，适合「记录一段时间再分析」：

trace-cmd record -p function_graph -g do_sys_openat2 -l 'vfs_*' sleep 2
trace-cmd report | head -30

hist 触发器：在内核里做聚合

ftrace 支持在事件上挂「histogram trigger」，不需要用户态逐条读：

# 按进程统计 sched_switch 次数
echo 'hist:keys=prev_comm:vals=hitcount:sort=hitcount:size=2048' \
     > events/sched/sched_switch/trigger
cat events/sched/sched_switch/hist

keys= 是分组键，vals= 是聚合值（hitcount、字段求和），sort= 排序，size= 桶数。这个能力在 4.7+ 就有，适合「快速看分布」而不引入 bpftrace。

3.15.4 perf：采样与硬件计数器

perf 有两类用法：计数（perf stat）与采样（perf record）。

# 计数：IPC、cache miss、分支预测、上下文切换
perf stat -e cycles,instructions,cache-misses,cache-references,\
branch-misses,page-faults,context-switches,cpu-migrations ./prog

# 采样：99 Hz，带调用栈，跑 10 秒
perf record -F 99 -g --call-graph dwarf -p $PID -- sleep 10
perf report --stdio | head -30

# 实时看热点
perf top -p $PID

# 跟踪系统调用（比 strace 轻）
perf trace -p $PID

# 调度延迟
perf sched latency -p $PID
perf sched record -- sleep 5 && perf sched report

perf stat 的几个关键指标：

采样堆叠成火焰图：

perf record -F 99 -g -- sleep 30
perf script > out.perf
stackcollapse-perf.pl out.perf > out.folded
flamegraph.pl out.folded > flame.svg

火焰图的读法：横轴是调用栈的字母序（不是时间），宽度是采样占比，纵向是调用深度。看「最宽的塔」找热点，看「平顶」（同一函数自己占满）找自旋/忙等。

perf 的权限由 kernel.perf_event_paranoid 控制：

生产环境通常设 2 或 3，普通用户不能采样内核；perf record -g 拿不到内核栈时，先看这个值。

3.15.5 bpftrace：可编程的动态探针

bpftrace 把「写一个 eBPF 程序」压缩成几行脚本。它的探针类型：

内置变量与函数：pid、tid、comm、nsecs、arg0..argN、retval、args、curtask、kstack、ustack、str()、count()、sum()、hist()、lhist()、avg()、min()、max()、delete()、clear()、print()。

几个能直接用的脚本：

# 1. 谁在打开文件（按进程聚合）
bpftrace -e 'tracepoint:syscalls:sys_enter_openat { @[comm] = count(); }'

# 2. read 的延迟直方图（微秒）
bpftrace -e '
kprobe:vfs_read { @start[tid] = nsecs; }
kretprobe:vfs_read /@start[tid]/
{
	@us = hist((nsecs - @start[tid]) / 1000);
	delete(@start[tid]);
}'

# 3. 每个进程的块 I/O 字节数（10 秒）
bpftrace -e '
tracepoint:block:block_rq_issue { @bytes[comm] = sum(args->bytes); }
interval:s:10 { exit(); }'

# 4. 跟踪某个函数的参数与返回值
bpftrace -e 'kprobe:do_sys_openat2 { printf("%s dfd=%d name=%s\n", comm, arg0, str(arg1)); }'

hist() 是对数分桶（2 的幂），lhist(value, min, max, step) 是线性分桶。@map 是全局聚合，@map[tid] 是按线程隔离。

bpftrace 的安全性由 eBPF 验证器保证：脚本不能有无限循环（5.3+ 允许有界循环）、不能越界访问、不能调用未授权的 helper。加载失败时 bpftool prog load 会给出验证器日志，定位到具体指令。

3.15.6 检查器：在崩溃前拦住 bug

KASAN

KASAN（Kernel Address Sanitizer）在编译时给每次内存访问插入检查，能抓到越界读写与 use-after-free：

# 配置
scripts/config -e KASAN -e KASAN_GENERIC -e KASAN_INLINE -e STACKTRACE
# 启动后如果越界，会打印：
BUG: KASAN: slab-out-of-bounds in mychar_write+0x4a/0x80
Write of size 8 at addr ffff888012345678 by task insmod/123
...
Allocated by task 123:
  kmalloc_trace+0x...
  mychar_init+0x...

代价是内存约 1.125 倍（shadow memory 1/8）与 2–3 倍时间，只在调试内核上开。KFENCE（5.12+）是「低开销抽样版」：每 100 ms 抽样一次分配，用独立的 guard page 检测越界，生产环境可常开。

KCSAN：数据竞争检测

KCSAN（CONFIG_KCSAN）用「看门狗」采样内存访问，检测没有同步保护的并发读写：

BUG: KCSAN: data-race in mychar_read / mychar_write
write to 0xffff888012345678 of 4 bytes by task 456 on cpu 1:
 mychar_write+0x...
read to 0xffff888012345678 of 4 bytes by task 123 on cpu 0:
 mychar_read+0x...

它抓的是「同一地址被两个 CPU 无同步地访问」，不要求真的产生错误结果。适合在 CI 里跑压力测试。

lockdep 与 hung task

3.11 已讲 lockdep。这里补三个运行时检查：

• hung task：khungtaskd 每 120 秒检查一次，发现 D 状态超过 hung_task_timeout_secs 的任务就打印调用栈；
• RCU stall：宽限期超过 21 秒（rcupdate.rcu_cpu_stall_timeout）没完成，打印所有 CPU 的栈与 RCU 状态；
• soft lockup / hard lockup：watchdog/N 在 2×watchdog_thresh（默认约 20 秒）内没被调度，报 BUG: soft lockup - CPU#N stuck for Xs；NMI watchdog 检测 CPU 长时间关中断，报 hard lockup。它和 hung task 的区别是：lockup 是 CPU 转不出来，hung task 是任务睡不醒。/proc/sys/kernel/watchdog、softlockup_panic、hardlockup_panic 控制行为，sysrq l 可打印所有 CPU 的栈。

三者都是「系统看起来卡住」时的第一手材料，比盲目 sysrq 更定向。

kmemleak

echo scan > /sys/kernel/debug/kmemleak
cat /sys/kernel/debug/kmemleak

它扫描内存找「没有指针指向的已分配块」，适合找模块卸载后的泄漏。误报率不低，要结合代码看。

3.15.7 崩溃分析：从 Oops 到 vmcore

读 Oops

BUG: unable to handle page fault for address: 0000000000000018
PGD 0 P4D 0
Oops: 0000 [#1] SMP PTI
CPU: 0 PID: 123 Comm: insmod Tainted: G           OE      6.8.0 #1
RIP: 0010:mychar_write+0x2a/0x80 [mychar]
Code: 48 8b 47 18 48 85 c0 74 0a ...
RSP: 0018:ffffc90000123c80 EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff888012345678 RCX: 0000000000000000
RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888087654321
Call Trace:
 <TASK>
 mychar_write+0x2a/0x80 [mychar]
 vfs_write+0x1c3/0x3f0
 ksys_write+0x6f/0xf0
 do_syscall_64+0x5f/0x110
 entry_SYSCALL_64_after_hwframe+0x6e/0x76

读的顺序：

1. 第一行：错误类型与地址。address: 0000000000000018 是典型的「空指针 + 偏移 0x18」，说明解引用了 NULL->field。
2. RIP：出错的指令地址与符号（mychar_write+0x2a），[mychar] 表示在模块里。
3. Code:：出错指令的机器码，配合 objdump -d mychar.ko 能找到源码行。
4. 寄存器：RAX=0 常常是空指针的来源；CR2（缺页地址）在 page fault 里给出具体地址。
5. Call Trace：调用链，从下往上读（entry_SYSCALL_64 → ksys_write → vfs_write → mychar_write）。
6. Tainted：G 表示 GPL 模块，O 表示 out-of-tree，E 表示 unsigned。上报 bug 时要带这行。

scripts/decode_stacktrace.sh 能把地址翻译成 file:line（需要 vmlinux 与源码）：

./scripts/decode_stacktrace.sh vmlinux /path/to/linux-6.8 < oops.txt

kdump 与 crash

配置 kdump 后，panic 时内核会启动一个「捕获内核」，把第一个内核的内存 dump 到 /var/crash/：

# 确认 kdump 在跑
systemctl status kdump-tools
cat /proc/cmdline | grep crashkernel

# 分析 vmcore
crash /usr/lib/debug/boot/vmlinux-6.8.0 /var/crash/2024-01-01/vmcore
crash> bt                 # 崩溃时的调用栈
crash> ps                 # 进程列表
crash> log                # 内核日志
crash> vm                 # 虚拟内存信息
crash> kmem -i            # 内存统计
crash> struct task_struct ffff888012345678
crash> dis mychar_write   # 反汇编

drgn 是更现代的替代品，用 Python 脚本访问 vmcore/活体内核，适合写自动化分析。

pstore 是另一种「事后」机制：panic 时把日志写进 ACPI ERST、EFI 变量或 ramoops 预留内存，重启后从 /sys/fs/pstore/ 读：

ls /sys/fs/pstore/
# dmesg-ramoops-0  console-ramoops-0
cat /sys/fs/pstore/dmesg-ramoops-0 | tail -50

sysrq：卡住时的应急手段

# 通过 /proc 触发（需要 root 且 kernel.sysrq 允许）
echo t > /proc/sysrq-trigger    # 打印所有任务
echo w > /proc/sysrq-trigger    # 打印阻塞任务
echo l > /proc/sysrq-trigger    # 所有 CPU 的栈
echo m > /proc/sysrq-trigger    # 内存信息
echo s > /proc/sysrq-trigger    # 同步
echo u > /proc/sysrq-trigger    # 重挂只读
echo b > /proc/sysrq-trigger    # 立即重启（不同步！）

物理键盘上是 Alt+SysRq+<key>。t/w/l 是安全的诊断；b/c 会丢数据，只在完全卡死时用。

3.15.8 性能分析：从症状到下钻

工具会用了，难的是「从哪个指标开始看」。推荐的顺序：

几个容易踩的方法论陷阱：

• 平均值骗人：P50 正常、P99 爆炸是常态；看分位数，不看均值。
• CPU 100% 不等于瓶颈：可能是自旋锁、可能是 GC、可能是「等 I/O 但被算成 CPU」。
• 缓存效应：第一次跑和第二次跑差几倍，先确认是不是 page cache/CPU cache 预热。
• 观测本身有开销：perf record -F 99 约 1–5%，ftrace function 可能 10%+，KASAN 2–3 倍。别在压测时开重工具，除非你要测的就是它。

3.15.9 实验：一次完整的取证

场景：mychar 驱动的 read 偶尔很慢。按「ftrace → perf → bpftrace」三步取证。

# 1. ftrace：看 read 路径上各函数耗时
cd /sys/kernel/tracing
echo function_graph > current_tracer
echo 'mychar_read' > set_graph_function
echo 1 > tracing_on
# 触发一次 read
./mychar_test
echo 0 > tracing_on
cat trace | head -30
# 如果 mychar_read 里 wait_event 占了大头，说明在等数据，不是 CPU 问题

# 2. perf：看是不是调度延迟
perf sched record -- ./mychar_test
perf sched latency | head -20
# 如果 mychar_test 的 max delay 很大，是等 CPU/被抢占

# 3. bpftrace：直接测 read 的端到端延迟分布
bpftrace -e '
kprobe:mychar_read { @s[tid] = nsecs; }
kretprobe:mychar_read /@s[tid]/
{
	@us = hist((nsecs - @s[tid]) / 1000);
	delete(@s[tid]);
}'

三段证据互相印证：ftrace 告诉你「时间花在哪个函数」，perf 告诉你「是不是没被调度」，bpftrace 给你「延迟分布」。单看任何一个都可能误判。

再给一个「内存泄漏」的取证脚本：

# 每 5 秒打印一次 slab 增长最快的 cache（需要 root）
bpftrace -e '
interval:s:5
{
	printf("--- %s ---\n", strftime("%H:%M:%S", nsecs));
	print(kstack(3));
}' 2>/dev/null

更实用的做法是对比两次 slabtop -s c -o 的输出，或用 kmemleak。bpftrace 更适合「按调用栈统计分配」，例如：

bpftrace -e 'tracepoint:kmem:kmalloc { @[kstack(4)] = sum(args->bytes_alloc); }'

3.15.10 printk 的内部：一条日志经过几道门

这一节回答：pr_info() 打印后，字符串先到哪里、什么时候出现在串口、为什么 dmesg 有时看不到最早的启动日志、/dev/kmsg 和 dmesg 有什么区别？

printk() 不是直接写串口。它先把格式化后的记录写进一个环形缓冲区（log_buf），再由 console 层异步/同步地送到各个 console（串口、VGA、netconsole、pstore）。这条管道决定了三件事：日志可能丢、日志可能延迟、日志的「时间」不等于「发生时间」。

记录格式与 ring buffer

每条 printk 记录在缓冲区里不是裸字符串，而是带元数据的 record：

/* kernel/printk/printk.c —— 6.8 节选，已简化 */
struct printk_record {
	const char *text;
	size_t text_len;
	struct printk_info *info;
};

struct printk_info {
	u64 seq;              /* 全局序号，单调递增 */
	u64 ts_nsec;          /* 记录时间（本地时钟） */
	u16 text_len;
	u16 dict_len;         /* 结构化字典（dev_printk 的键值） */
	u8 facility;
	u8 flags;             /* 是否 extended、是否紧急 */
	u8 level;             /* 0–7 */
	u8 caller_id;         /* 调用者 id，需 CONFIG_PRINTK_INDEX */
};

log_buf 是一个 prb（printk ring buffer），写满后覆盖最旧的记录。默认大小由 CONFIG_LOG_BUF_SHIFT 决定（常见 18 → 256 KiB），启动参数 log_buf_len=1M 可改。覆盖行为解释了：

• 启动早期日志量大时，dmesg 开头会被截断；
• 长期运行的机器上，dmesg 只保留最近一段；
• dmesg -w 只能跟到「从现在开始」的新记录，历史已经不在缓冲区里。

要看完整启动日志，用 journalctl -k -b（systemd 在启动时把 /dev/kmsg 读走并落盘），或配置 pstore/ramoops 保存 panic 前的最后一段。

console 注册与输出路径

console 是一个实现了 struct console 的设备：

struct console {
	char name[16];
	void (*write)(struct console *co, const char *s, unsigned int count);
	int (*read)(struct console *co, char *s, unsigned int count);
	struct tty_driver *(*device)(struct console *co, int *index);
	void (*unblank)(void);
	int (*setup)(struct console *co, char *options);
	int (*exit)(struct console *co);
	short flags;          /* CON_PRINTBUFFER / CON_CONSDEV / CON_ENABLED ... */
	short index;
	int cflag;
	...
};

注册后，console->flags 的 CON_PRINTBUFFER 决定它是否补打缓冲区里的历史日志。串口 console 通常带这个标志，所以内核启动到串口驱动注册之间的日志，会在注册后一次性补出来——这就是「early boot 日志看起来时间很晚」的原因。

/proc/sys/kernel/printk 的四个数字分别控制：

echo 8 > /proc/sys/kernel/printk 实际只改第一个数字（其余保持），所以 cat 会看到 8 4 1 7。dmesg -n 8 是同一个操作的封装。

/dev/kmsg 与 dmesg

dmesg 读的是 syslog(2) 系统调用（或 /dev/kmsg），两者访问同一个 ring buffer，但语义不同：

/dev/kmsg 的写入格式是 PRIORITY;FACILITY;...，普通进程需要 CAP_SYSLOG（或 dmesg_restrict=0）。容器里经常把 /dev/kmsg 只读挂载，导致应用写日志失败——这不是内核 bug，是权限设计。

限流与「日志风暴」

热路径上大量 printk 会拖垮系统：每条记录要抢 logbuf_lock（早期是全局锁，5.10 后改成 per-cpu 的 prb），console 输出可能同步等串口。内核提供三级保护：

1. printk_ratelimit() / pr_*_ratelimited()：每 5 秒最多 10 条，超了打印 callbacks suppressed；
2. console_verbose() / loglevel：调试时临时提高级别；
3. printk.suppress_message_printing()：对重复消息按 printk_delay 与哈希抑制（5.10+ 的 suppress_message_printing）。

更彻底的做法是把热路径日志换成 trace_printk()：它写 ftrace 的 per-cpu ring buffer，不经过 console，开销从微秒级降到几十纳秒。代价是 trace_printk 的输出只能用 cat trace 看，不会进 dmesg，也不能长期开启（缓冲区会覆盖）。

/* 热路径：不要用 printk */
trace_printk("tx len=%u dma=%pad\n", len, &dma);

/* 冷路径/错误路径：printk 可以 */
if (unlikely(ret))
	dev_err_ratelimited(&pdev->dev, "tx failed: %d\n", ret);

动态调试的匹配语法

dynamic_debug 的控制文件支持按文件、函数、行号、模块、格式串匹配：

# 打开本模块所有 pr_debug，并附加函数名/行号/模块名/线程号
echo 'module misc_demo +pflmt' > /sys/kernel/debug/dynamic_debug/control

# 只打开某文件某函数
echo 'file misc_demo.c func demo_read +p' > /sys/kernel/debug/dynamic_debug/control

# 查看当前已打开的点
grep '=p' /sys/kernel/debug/dynamic_debug/control | head

标志位：p 打印、f 函数名、l 行号、m 模块名、t 线程 id。启动参数 dyndbg="file misc_demo.c +p" 可以在模块加载前就打开，适合调试 probe 早期路径。

3.15.11 ftrace 的实现：mcount、fentry 与 ring buffer

这一节回答：echo function > current_tracer 之后，内核怎么做到「不改代码就追踪所有函数」？为什么 function_graph 比 function 贵一个数量级？trace_pipe 与 trace 有什么区别？

ftrace 的起点是编译期插桩。早期用 gcc 的 -pg 在每个函数入口插入 mcount 调用；现代内核（x86-64）默认用 -mfentry，在函数第一条指令之前插入 call __fentry__。两者差别很重要：

• mcount 在函数序言之后，此时栈帧已建立，取参数方便，但会破坏「函数第一条指令」的假设；
• fentry 在序言之前，栈还是调用者的，开销更小，且可以和 -fpatchable-function-entry 配合做静态调用点（static call）。

启动时，ftrace 把 __fentry__ 的位置替换成 nop（5 字节），所以未启用时开销接近零；启用 function tracer 时，把 nop 改回 call 到 trampoline，由 trampoline 把 ip、parent_ip 写进 per-cpu ring buffer。这个过程叫 ftrace_patch，通过 text_poke 修改只读代码段。

ring buffer 的写入

每条 function 记录只有几个字段：

/* include/linux/trace_events.h —— 6.8 节选 */
struct ftrace_entry {
	struct trace_entry ent;   /* type, flags, preempt_count, pid */
	unsigned long ip;         /* 被调用函数地址 */
	unsigned long parent_ip;  /* 调用者地址 */
};

trace 文件是「快照」：读之前内核会 trace_stop() 并 splice 出当前缓冲区；trace_pipe 是「流」：每次 read() 消费一条，适合 cat trace_pipe | grep 长时间跟。两者都会阻塞/竞争，生产上更常用 per_cpu/cpuN/trace 分 CPU 读，避免全局锁。

function_graph 多记了什么？它在函数入口和返回各插一个 hook，维护一个 per-task 的调用深度栈，返回时用 now - entry_time 算耗时，并按深度缩进。因此：

• 记录量约为 function 的 2 倍；
• 每条记录多一次时间戳读取（local_clock()）；
• 要保证入口/返回配对，异常/长跳转会破坏缩进（内核用 return_to_handler 修正）。

tracefs 的目录结构

/sys/kernel/tracing/
├── available_tracers          # 编译进来的 tracer
├── available_filter_functions # 可被 function tracer 插桩的函数
├── current_tracer             # nop/function/function_graph/irqsoff/...
├── set_ftrace_filter          # function tracer 的白名单
├── set_ftrace_notrace         # 黑名单（优先级更高）
├── set_graph_function         # function_graph 的根函数
├── set_graph_notrace          # 调用树里剪掉的分支
├── events/                    # tracepoint 与 kprobe 事件
├── instances/                 # 多实例，每个实例独立缓冲区
├── per_cpu/cpu0/trace         # 分 CPU 快照
├── trace                      # 全局快照
├── trace_pipe                 # 流式读取
├── trace_clock                # local/global/counter/x86-tsc
└── tracing_on                 # 0/1 开关

instances/ 是一个容易被忽略的能力：不同子系统可以各自建一个实例，独立开关、独立缓冲区，互不覆盖。容器场景常用它给每个容器一个 trace 实例。

事件、hist 与 synthetic event

tracepoint 事件在 events/<subsystem>/<event>/ 下，每个事件有 enable、filter、trigger、format。format 是稳定的字段描述，用户态工具（perf、bpftrace、trace-cmd）靠它解析二进制记录。

hist 触发器把聚合下推到内核：

# 按进程统计 sched_switch 的命中次数，并按次数排序
echo 'hist:keys=prev_comm:vals=hitcount:sort=hitcount:size=4096' \
     > events/sched/sched_switch/trigger
cat events/sched/sched_switch/hist

# 按调用者统计 kmalloc 的字节数（需要 kmem 事件）
echo 'hist:keys=call_site:vals=bytes_req:sort=bytes_req.descending' \
     > events/kmem/kmalloc/trigger

hist 的 key 可以是字段、common_pid、call_site；value 支持 hitcount、字段求和、min/max。它不需要 bpftrace，适合「只想快速看分布」的场景；但表达能力有限，不能写任意条件聚合。

synthetic 事件（4.17+）允许把两个事件的字段拼成一个新事件：

# 定义 synth 事件：保存 sched_switch 的 prev_pid，在 sched_wakeup 时配对
echo 'sched_switch prev_pid=prev_pid prev_prio=prev_prio' > synthetic_events
echo 'sched_wakeup pid=pid prio=prio' >> synthetic_events
echo 'hist:keys=prev_pid:vals=hitcount' > events/sched/sched_switch/trigger

更实用的用法是「延迟配对」：wakeup 记时间戳，switch 读时间戳算差值。这类脚本用 bpftrace 写更直观，但 synthetic event 的优势是零用户态开销，适合高频事件。

trace-cmd：把 ftrace 变成「记录-分析」工作流

# 记录 5 秒的 sched 事件与函数图
trace-cmd record -p function_graph -g do_sys_openat2 -e sched -l 'vfs_*' -- sleep 5
# 文本报告
trace-cmd report | head -40
# 导出为 Chrome trace / kernelshark
trace-cmd report --version
trace-cmd record -p function -e block -o trace.dat -- sleep 2

trace-cmd 的价值是「把 trace.dat 带到另一台机器分析」，避免在生产机上装 GUI。kernelshark 是它的图形前端，适合看调度时序。

3.15.12 perf 的事件模型：从 PMU 到 ring buffer

这一节回答：perf record -F 99 的 99 Hz 是谁在计时？采样点为什么有时落在 unknown？perf stat 的 cycles 与 task-clock 有什么区别？perf_event_paranoid 到底挡住了什么？

perf 的核心是一个系统调用：perf_event_open(2)。它把一个「事件」绑定到 CPU 或进程上，事件可以是：

perf stat 用的是计数模式（PERF_EVENT_IOC_ENABLE 后读计数器），没有采样开销；perf record 用的是采样模式（sample_period 或 sample_freq），每个事件溢出时写一条样本到 mmap 的 ring buffer。

采样频率与精度

-F 99 表示 99 Hz，即每 CPU 每秒约 99 个样本。为什么不是 100？避免与 100 Hz 的调度 tick 锁相（lockstep），否则每次都在同一个 tick 边界采样，得到有偏的分布。同理，-F 99 也是 perf 的默认建议值。

采样点由 PMU 的溢出中断触发，硬件计数器在 skid 之后才停，所以 perf record 的 ip 可能不是精确的「第一条超标指令」，而是往后几条。对热点定位够用，对指令级调优要用 PEBS（Precise Event-Based Sampling）：

# Intel PEBS：精确到指令
perf record -e cycles:pp -F 999 -- ./prog
# AMD IBS
perf record -e ibs_op// -F 999 -- ./prog

cycles:pp 的 pp 表示 precise level 2；不支持 PEBS 的机器会退化成普通采样，perf report 里会提示。

callchain 的三种采集方式

perf record -g 抓调用栈，底层有三种：

1. frame pointer（--call-graph fp）：依赖 -fno-omit-frame-pointer，最快，但内核/库经常省略帧指针，栈会断；
2. DWARF（--call-graph dwarf）：用 .eh_frame/.debug_info 展开，最准，但样本文件大、CPU 开销高；
3. LBR（--call-graph lbr）：Intel Last Branch Record，硬件记录最近的分支，适合短栈，深度有限。

生产上如果编译时保留了帧指针，用 fp；否则 dwarf 但降低频率。perf report --no-children 可以看「自身耗时」而不是「包含子调用」的耗时，定位热点更直接。

off-CPU 分析与 perf sched

CPU 采样只能看到「在 CPU 上跑」的时间。如果进程大部分时间在等锁/等 I/O/等调度，perf top 里它根本不出现。这时要换 off-CPU 分析：

# 调度延迟：任务从可运行到真正上 CPU 的时间
perf sched record -- sleep 5
perf sched latency

# 上下文切换明细
perf sched script | head -30

# off-CPU 时间（需要 bpftrace 或 perf inject）
bpftrace -e '
tracepoint:sched:sched_switch
/args->prev_state == 1/       /* TASK_INTERRUPTIBLE */
{ @sleep[args->prev_comm] = sum(args->next_prio); }'

perf sched latency 的输出里，Max delay 是「最坏调度延迟」，Avg delay 是平均。一个进程 CPU 使用率不高但延迟毛刺大，通常是 Max delay 而不是 CPU 本身的问题。

perf_event_paranoid 与权限

普通用户 perf record -g 拿不到内核栈，通常不是符号问题，而是这个值。临时放开：

sudo sysctl kernel.perf_event_paranoid=1
# 或只给当前会话
sudo sh -c 'echo 1 > /proc/sys/kernel/perf_event_paranoid'

容器里还要看 perf_event_open 的 seccomp 策略；很多容器运行时默认拦截 perf_event_open，表现为 Permission denied 而不是 EINVAL。

3.15.13 bpftrace 与 eBPF：可编程探针的边界

这一节回答：bpftrace 脚本为什么能「一次编译、跨内核版本运行」？kprobe、tracepoint、fentry 三种探针在底层有什么不同？为什么有些脚本一加载就被验证器拒绝？

bpftrace 的运行时是 eBPF：脚本被编译成 eBPF 字节码，经 verifier 检查后 JIT 成机器码，挂在探针上。它和 ftrace 的区别是「可编程」：ftrace 的 hist 触发器只能做固定聚合，bpftrace 能写任意条件、Map 聚合、调用栈、甚至修改返回值（override()）。

探针的四种挂载方式

kprobe 的实现是「把目标地址的第一条指令替换成断点」，命中后由 do_int3 保存上下文、调用 handler、单步执行原指令。fentry 则是编译期在函数入口留 5 字节 nop，运行时用 text_poke 改成 call 到 trampoline，不需要单步，开销更低，也不会与 ftrace 的 fentry 冲突（两者共享同一个调用点，由 ftrace 协调）。

BTF 与 CO-RE：跨版本的关键

传统 eBPF 程序在访问 struct task_struct 字段时，需要把偏移硬编码；内核结构一变就崩。CO-RE（Compile Once – Run Everywhere）用 BTF（BPF Type Format）解决：

• 编译时，clang 把字段访问记录成重定位（BTF_KIND_FIELD + 偏移占位）；
• 加载时，libbpf 读内核的 /sys/kernel/btf/vmlinux，按字段名重新计算偏移；
• 如果字段不存在，加载失败并给出明确错误，而不是运行时读错内存。

# 内核是否导出 BTF
ls -l /sys/kernel/btf/vmlinux
bpftool btf dump file /sys/kernel/btf/vmlinux format c | head -30

# bpftrace 查看可用的 tracepoint 与 kprobe 符号
bpftrace -l 'tracepoint:sched:*'
bpftrace -l 'kprobe:vfs_*' | head

bpftrace 6.x 默认用 BTF 解析 args->，所以 tracepoint:... { args->field } 不需要手写偏移。kprobe 的 arg0..argN 是寄存器/栈参数，没有类型信息；要读结构体字段，得用 ((struct task_struct *)arg0)->pid，并确保该结构体在 BTF 里可见。

Map、聚合与输出

bpftrace 的 @ 变量是 Map，按 key 聚合：

@counts[comm] = count();                 // hash map: string -> u64
@bytes[pid] = sum(args->bytes);          // 求和
@lat = hist((nsecs - @start[tid]) / 1000); // 对数直方图
@dist = lhist(value, 0, 1000, 10);       // 线性直方图

Map 的类型在编译期推断；key 可以是整数、字符串、元组（@x[comm, pid]）。print(@map) 输出全部，clear(@map) 清空但保留结构，delete(@map[key]) 删单个 key。interval:s:5 { print(@); clear(@); } 是「周期性快照」的标准写法。

输出到终端用 printf()，写到 perf ring buffer 用 print()；高频事件不要逐条 printf，会拖慢系统。更好的做法是聚合后周期性打印，或用 ringbuf map 批量消费。

验证器在拦什么

eBPF verifier 的目标是「保证程序不会崩溃内核」。它做抽象解释，检查：

1. 内存安全：所有指针访问必须在已知边界内；arg0 是 u64，不能直接解引用，要先 probe_read/bpf_probe_read_kernel；
2. 有界循环：5.3+ 允许有界循环，但必须能证明会终止；while (1) 被拒绝；
3. 调用限制：只能调用允许的 helper，且参数类型匹配；
4. 栈大小：每个 BPF 程序栈上限 512 字节，大结构要放 Map；
5. 指令数：历史上限 4096 条（复杂程序 1M），bpftrace 生成的代码可能超限。

加载失败时，bpftool prog load 会打印 verifier 日志，逐条指令说明「哪一步丢了什么类型」。bpftrace 加 -v 也能看到。常见错误：

R1 type=ctx expected=fp
invalid read from stack off -8 size 8
back-edge from insn 12 to 8

第一行是「把 ctx 当栈指针用」，第二行是「读未初始化的栈」，第三行是「循环没有可证明的边界」。

生产可用的五个脚本

# 1. 打开文件失败的原因分布（errno）
bpftrace -e '
tracepoint:syscalls:sys_exit_openat /args->ret < 0/
{ @errno[-args->ret] = count(); }
interval:s:10 { exit(); }'

# 2. 块 I/O 延迟直方图（us）
bpftrace -e '
tracepoint:block:block_rq_issue { @start[args->dev, args->sector] = nsecs; }
tracepoint:block:block_rq_complete /@start[args->dev, args->sector]/
{
	@us = hist((nsecs - @start[args->dev, args->sector]) / 1000);
	delete(@start[args->dev, args->sector]);
}'

# 3. 调度延迟（run queue latency）
bpftrace -e '
tracepoint:sched:sched_wakeup { @q[args->pid] = nsecs; }
tracepoint:sched:sched_switch /@q[args->next_pid]/
{
	@us = hist((nsecs - @q[args->next_pid]) / 1000);
	delete(@q[args->next_pid]);
}'

# 4. kmalloc 调用栈 Top（按字节）
bpftrace -e 'tracepoint:kmem:kmalloc { @[kstack(5)] = sum(args->bytes_alloc); }'

# 5. 某进程的 read 延迟（含返回长度）
bpftrace -e '
kprobe:vfs_read /pid == $1/ { @s[tid] = nsecs; }
kretprobe:vfs_read /@s[tid]/
{
	@us = hist((nsecs - @s[tid]) / 1000);
	delete(@s[tid]);
}' -p $(pgrep -n myapp)

脚本 2 的 key 用 (dev, sector) 而不是 args->rq，是因为 block_rq_complete 的 args 里不一定有同一个指针；用设备+扇区配对更稳，但仍可能被合并/拆分的请求干扰。生产上更推荐 biolatency（BCC）或 perf 的 block tracepoint。

3.15.14 检查器：KASAN、KFENCE、KCSAN 与 lockdep

这一节回答：KASAN 的 1/8 shadow memory 是怎么算出来的？KFENCE 为什么能在生产环境常开？KCSAN 报的 data-race 为什么有些是误报？lockdep 的「锁类」图到底在证明什么？

这四种工具的共性：它们不依赖「崩溃发生」，而是在访问发生的瞬间判断是否合法。区别在检测对象与开销。

KASAN：影子内存

KASAN 给每个内存字节分配一个 shadow 字节，记录「这 8 个字节是否可访问」：

应用内存:   [ 0 1 2 3 4 5 6 7 ][ 8 9 ... ]
shadow:     [ 0 ][ 0 ][ 0 ][ 0 ] ...   （0 表示 8 字节全部可访问）
越界后:     [ 3 ]                       （前 3 字节可访问，后 5 字节是红区）

地址换算：shadow = (addr >> 3) + KASAN_SHADOW_OFFSET。因此 shadow 占应用内存的 1/8，这就是「1.125 倍内存」的来源。访问时编译器插入检查：

/* 编译后（概念上） */
if (*(u8 *)((addr >> 3) + offset) != 0)
	kasan_report(addr, size, is_write, ip);

模式：

• CONFIG_KASAN_GENERIC：完整红区，检测越界/use-after-free，开销 2–3 倍；
• CONFIG_KASAN_SW_TAGS（ARM64）：用指针高字节存 tag，内存开销更低；
• CONFIG_KASAN_HW_TAGS（MTE）：硬件 tag，接近生产可用；
• CONFIG_KASAN_INLINE：检查内联到访问点，快但代码膨胀；OUTLINE 用函数调用，代码小。

KASAN 报告的关键字段：

BUG: KASAN: slab-out-of-bounds in misc_demo_write+0x4a/0x80
Write of size 8 at addr ffff888012345678 by task misc_test/123
Allocated by task 123:
  kmalloc_trace+0x... 
  misc_demo_init+0x...
Freed by task 0:
  kfree+0x...

读法：先看「越界类型 + 访问大小 + 地址」，再看 Allocated by / Freed by 的调用栈。slab-out-of-bounds 是 slab 红区，use-after-free 是已释放对象，global-out-of-bounds 是全局变量越界。addr 的低位能看出偏移。

KFENCE：抽样但低开销

KFENCE（5.12+）不追踪所有分配，而是按 sample_interval（默认 100 ms）抽样，把抽中的对象放在独立的 guard page 旁边。越界访问会命中 guard page 触发 page fault，use-after-free 则把对象隔离一段时间再释放。

开销接近零（约 1%），可以在生产常开；代价是只能抓到抽样到的 bug，概率性。配置：

# 启动参数：每 100ms 采样一次，最多 255 个对象
kfence.sample_interval=100 kfence.num_objects=255
# 运行时状态
cat /sys/kernel/debug/kfence/stats

KFENCE 报告与 KASAN 类似，但会注明 kfence: ...，且没有完整 shadow，不能定位「读越界 1 字节」这类小偏移。

KCSAN：数据竞争的采样检测

KCSAN 用「watchpoint + 延迟」检测无同步的并发访问：它给内存打标记，当一个 CPU 读、另一个 CPU 写同一地址且没有 happens-before 关系时报告。它检测的是「数据竞争」而不是「数据损坏」，所以：

• 两个线程都持同一把锁的临界区不会报；
• 用 READ_ONCE()/WRITE_ONCE() 的无锁访问不会报（它们有标记）；
• 用 atomic_t 的访问不会报。

报告里的 write to ... by task A / read to ... by task B 给出两侧调用栈。误报常见于「用 barrier 但 KCSAN 不认识」的代码，需要 __no_kcsan 或 data_race() 标注。

lockdep：锁类的有向图

lockdep 不看具体锁实例，而是看锁类（相同初始化点的锁）。每次获取锁时，它记录「当前任务已持有哪些锁类」，并在图上加边 A → B；如果加入这条边会形成环，就报告「可能的死锁」。

======================================================
WARNING: possible circular locking dependency detected
------------------------------------------------------
bash/1234 is trying to acquire lock:
 (&sb->s_type->i_mutex_key){+.+.}, at: ...
but task is already holding lock:
 (&mm->mmap_lock){++++}, at: ...
which lock already depends on the new lock.

读法：{+.+.} 是锁的状态位（是否可睡眠、是否在中断上下文获取等）；which lock already depends on 下面的链就是环。lockdep 的代价是每个锁操作多几次原子操作与图查询，通常 5–15%。

hung task 不是 lockdep，它检测「D 状态超过 120 秒」；soft lockup 检测「CPU 20 秒没调度」；RCU stall 检测「宽限期 21 秒没完成」。四者常一起开，覆盖「死锁、活锁、睡死、RCU 卡死」。

3.15.15 实验：给一个模块做「三层取证」

这一节回答：同一个延迟问题，怎样用 ftrace、perf、bpftrace 三种证据交叉验证，而不是只贴一张火焰图就下结论？

实验对象是一个故意引入延迟的模块：它每秒跑一次 work，work 里 msleep(delay_ms)，并把最近一次耗时写到 debugfs。延迟来源明确，正好用来校准三套工具。

模块：trace_demo.c

// trace_demo.c — 可调延迟的 work，供 ftrace/perf/bpftrace 观测（Linux 6.8）
#include <linux/debugfs.h>
#include <linux/delay.h>
#include <linux/init.h>
#include <linux/ktime.h>
#include <linux/module.h>
#include <linux/workqueue.h>

static unsigned int delay_ms = 5;
module_param(delay_ms, uint, 0644);
MODULE_PARM_DESC(delay_ms, "sleep time in work (ms)");

static struct delayed_work demo_work;
static struct dentry *demo_dir;
static u64 last_ns;

static void demo_work_fn(struct work_struct *work)
{
	u64 t0 = ktime_get_ns();

	trace_printk("trace_demo: begin delay=%u\n", delay_ms);
	msleep(delay_ms);
	last_ns = ktime_get_ns() - t0;
	trace_printk("trace_demo: end elapsed=%llu ns\n", last_ns);

	schedule_delayed_work(&demo_work, msecs_to_jiffies(1000));
}

static int __init trace_demo_init(void)
{
	demo_dir = debugfs_create_dir("trace_demo", NULL);
	debugfs_create_u32("delay_ms", 0644, demo_dir, &delay_ms);
	debugfs_create_u64("last_ns", 0444, demo_dir, &last_ns);

	INIT_DELAYED_WORK(&demo_work, demo_work_fn);
	schedule_delayed_work(&demo_work, 0);
	pr_info("trace_demo: loaded, delay_ms=%u\n", delay_ms);
	return 0;
}

static void __exit trace_demo_exit(void)
{
	cancel_delayed_work_sync(&demo_work);
	debugfs_remove_recursive(demo_dir);
	pr_info("trace_demo: unloaded\n");
}

module_init(trace_demo_init);
module_exit(trace_demo_exit);
MODULE_LICENSE("GPL");
MODULE_DESCRIPTION("delayed work for ftrace/perf/bpftrace calibration");

加载后：

sudo insmod trace_demo.ko delay_ms=20
cat /sys/kernel/debug/trace_demo/last_ns
# 20000000 左右（msleep 的精度通常在 +1~5 ms）
echo 50 | sudo tee /sys/kernel/debug/trace_demo/delay_ms

msleep(20) 实际睡 20–25 ms 是正常的：msleep() 基于 jiffies，HZ=250 时一个 tick 是 4 ms，会向上取整。

第一层：ftrace 看「时间花在哪个函数」

cd /sys/kernel/tracing
echo 0 > tracing_on
echo function_graph > current_tracer
echo 'demo_work_fn' > set_graph_function
echo 1 > tracing_on
sleep 2
echo 0 > tracing_on
cat trace | sed -n '1,50p'

预期看到：

 1)               |  demo_work_fn() {
 1)               |    msleep() {
 1) * 21000 us   |      schedule_timeout();
 1) * 21005 us   |    }
 1) * 21010 us   |  }

* 表示超过了 set_graph_function 的阈值。如果 msleep() 只占 2 ms，而 demo_work_fn 占 20 ms，说明延迟在 schedule_delayed_work() 或 ktime_get_ns() 之外的代码；如果 schedule_timeout() 占了大头，说明就是睡眠，不是 CPU 问题。

第二层：perf 看「是不是没被调度」

# 记录 5 秒的调度事件
sudo perf sched record -- sleep 5
sudo perf sched latency | head -20

输出里找 kworker/u*（workqueue 的 worker）的 Max delay。如果 Max delay 接近 20 ms，说明 worker 从被唤醒到上 CPU 等了很久；如果 Max delay 很小而 demo_work_fn 仍然慢，问题在 work 内部（msleep 或锁）。

也可以直接测 workqueue 的排队延迟：

sudo bpftrace -e '
tracepoint:workqueue:workqueue_queue_work
{ @q[args->work] = nsecs; }
tracepoint:workqueue:workqueue_execute_start
/@q[args->work]/
{
	@us = hist((nsecs - @q[args->work]) / 1000);
	delete(@q[args->work]);
}'

workqueue_queue_work 的 args->work 是指针，能配对到 execute_start；如果没配对到，@q 会增长，结束时用 clear(@q)。

第三层：bpftrace 看「端到端分布」

sudo bpftrace -e '
kprobe:demo_work_fn { @s[tid] = nsecs; }
kretprobe:demo_work_fn /@s[tid]/
{
	@us = hist((nsecs - @s[tid]) / 1000);
	delete(@s[tid]);
}
interval:s:5 { exit(); }'

输出是按 2 的幂分桶的直方图。msleep(20) 的分布应集中在 16–32 ms 桶；如果出现 64 ms、128 ms 的长尾，说明 worker 被抢占或 workqueue 拥塞。三次实验把「函数内部睡眠」「调度延迟」「端到端长尾」分开，结论才可靠。

用户态对照：nanosleep 的抖动

内核侧的 msleep 与用户侧的 nanosleep 都会受调度粒度影响。下面这个程序请求固定睡眠，统计「实际睡眠 - 请求睡眠」的分布，用来判断抖动来自定时器、调度还是负载：

/* sched_jitter.c — 测量 nanosleep 的相对误差分布
 * 编译: cc -std=c17 -D_GNU_SOURCE -Wall -Wextra -Werror -O2 -o sched_jitter sched_jitter.c
 */
#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <time.h>

#define N 200

static int cmp_long(const void *a, const void *b)
{
	long x = *(const long *)a, y = *(const long *)b;

	return (x > y) - (x < y);
}

int main(void)
{
	const long req_ns = 1000000;      /* 请求 1 ms */
	struct timespec ts = { 0, req_ns };
	long delta[N];
	int i;

	for (i = 0; i < N; i++) {
		struct timespec a, b;
		long elapsed;

		clock_gettime(CLOCK_MONOTONIC, &a);
		if (nanosleep(&ts, NULL) < 0) {
			perror("nanosleep");
			return 1;
		}
		clock_gettime(CLOCK_MONOTONIC, &b);
		elapsed = (b.tv_sec - a.tv_sec) * 1000000000L + (b.tv_nsec - a.tv_nsec);
		delta[i] = elapsed - req_ns;
	}

	qsort(delta, N, sizeof delta[0], cmp_long);
	printf("min=%ldus p50=%ldus p90=%ldus p99=%ldus max=%ldus\n",
	       delta[0] / 1000, delta[N / 2] / 1000, delta[N * 9 / 10] / 1000,
	       delta[N * 99 / 100] / 1000, delta[N - 1] / 1000);
	return 0;
}

在空闲机器上，1 ms 睡眠的误差通常在几十微秒；如果 p99 到几毫秒，说明定时器精度（CONFIG_HZ）或 CPU 被抢占。把 chrt -f 50 ./sched_jitter 再跑一次，如果长尾消失，问题在调度策略而不是定时器。

第四层：崩溃取证（可选，QEMU 内做）

在 QEMU 里加载一个故意空指针的模块，触发 panic 后走一遍 kdump：

# 虚机内：确认 kdump 已配置
cat /proc/cmdline | grep crashkernel
systemctl status kdump-tools 2>/dev/null || true
# 触发 panic（只在实验虚机里！）
echo c > /proc/sysrq-trigger
# 重启后
ls -l /var/crash/*/vmcore
crash /usr/lib/debug/boot/vmlinux-$(uname -r) /var/crash/*/vmcore

crash 里按顺序执行：

crash> bt            # 崩溃 CPU 的调用栈
crash> log | tail    # panic 前的 dmesg
crash> ps            # 进程列表，看谁在跑
crash> kmem -i       # 内存水位与 slab
crash> struct page ffff888012345678
crash> dis demo_work_fn

bt 给出「谁在什么函数里崩」，log 给出「崩溃前发生了什么」，ps 排除「是不是某个进程把内存吃光」，kmem -i 看是否 OOM。四步之后再回到源码，比一上来 objdump 高效。

3.15.16 本章出口检查

母本对应

下一站：第 3 篇到此结束。你已经走完「启动 → 中断/系统调用 → 进程 → 调度 → 内存 → 同步 → 文件系统 → 块层 → 驱动 → 观测」的完整内核地图。接下来可以走第 4 篇 网络，把 socket、协议栈与内核收发包路径接上；或者直接进项目 A3，用 eBPF 写一个自己的可观测性工具。