Linux ftrace 内核追踪：从 function_graph 到 kprobe 动态事件

Linux ftrace 内核追踪：从 function_graph 到 kprobe 动态事件

一个进程卡住了、一次系统调用比预期慢十倍、某个内核函数到底被谁调用——这些问题有几个常见的答案：strace 看系统调用、perf 采样找热点、抓包看网络。但它们都在内核的「外面」：strace 靠 ptrace 把进程拦下来问话，perf 靠 PMU 计数器定期采样。

ftrace 不一样，它就在内核里面：内核编译时就留好了钩子（-pg 打桩），运行时把感兴趣的调用记进一块环形缓冲区，用户态只需要往几个文本文件里 echo。

它的门槛低到有点反直觉——不需要装包、不需要编译模块、不需要 root 之外的特权，因为整套东西就是内核自带的一个伪文件系统。

ftrace 是什么：一个挂在 tracefs 上的内核框架

先看「器材清单」：

cd /sys/kernel/tracing
cat available_tracers
echo "可用函数总数: $(wc -l < available_filter_functions)"
echo "缓冲区大小: $(cat buffer_size_kb) KB"

hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
可用函数总数: 53587
缓冲区大小: 1408 KB

这四行信息量很大：

• available_tracers 是当前内核编进去的追踪器名单。本文会用到 function（记录每一次函数调用）、function_graph（记录调用关系与每层耗时）；nop 是「什么都不追踪」，是干净的默认状态；wakeup / wakeup_rt 用来查唤醒延迟，hwlat 查硬件造成的延迟尖峰，blk 看块设备。
• 53587 个函数可以被单独点名，这是后面「收窄追踪范围」的底气。
• 缓冲区只有 1408 KB（单核机器，每核一份）。这是个环形缓冲区：写满了就覆盖最老的记录，所以它不会吃内存，但也不适合长时间挂着录——要么收窄范围，要么及时把 trace 读出来。

两个挂载点都是同一份数据，实测 inode 相同：

stat -c '%d:%i %n' /sys/kernel/tracing/trace_marker /sys/kernel/debug/tracing/trace_marker

12:12458 /sys/kernel/tracing/trace_marker
12:12458 /sys/kernel/debug/tracing/trace_marker

老教程会写 /sys/kernel/debug/tracing/，新内核推荐 /sys/kernel/tracing/（需要 debugfs 挂载才能用的路径，在部分发行版上会是空的）。两者指向同一个文件，用哪个都行，本文统一用后者。

三个开关：tracer、tracing_on、trace

ftrace 的所有操作，都是在往文本文件里写字符串。理解这三个文件，就理解了它的运行模型：

三个容易踩的点：

1. trace 是快照读取，不是「取走」。读它不会清空缓冲区，也不要求先停掉录制——实测在 tracing_on=1 的状态下直接 cat trace 就能读到已录到的部分。
2. 清空缓冲区是「截断」：echo > trace（等价于 : > trace）。往里 echo 0 不会清空。
3. 切换追踪器之前先 echo 0 > tracing_on，否则切换瞬间录到的半截调用会让输出看起来莫名其妙。

一个最小的复位组合，本文后面的每段演示开头都会跑一次：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace

nop 之后再装新追踪器，是比「直接换」更安全的姿势。

function_graph：把一次 read 的内核路径摊开

先看最有观感的一个：调用树。

function_graph 用编译器插桩记录函数的进入和返回，于是能画出「谁调用了谁、每层花了多久」。用 set_graph_function 指定树的根，max_graph_depth 限制层数（不限制的话，一次文件读取能展开上万行）：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace
echo vfs_read > set_graph_function
echo 2 > max_graph_depth
echo function_graph > current_tracer
echo 1 > tracing_on
sh -c 'echo $$ > set_ftrace_pid; exec cat /etc/hostname > /dev/null'
echo 0 > tracing_on
grep -v '^#' trace | head -16

先解释那条略拗口的 sh -c 行：exec 会让 cat 继承 shell 的 PID，所以 echo $$ > set_ftrace_pid 写进去的正是 cat 的 PID——这样被追踪的只有这一个进程，而不是全系统。少了这一句，缓冲区里会混进脚本自己读标准输入产生的调用。

输出怎么读：

• 第一列 0) 是 CPU 编号，本文演示机只有 1 核，所以恒为 0；多核机器上这一列会跳来跳去。
• 中间是耗时，| 那一列是调用层级——缩进越深，调用栈越深。
• vfs_read() { 开头、} 结尾，} 那一行的耗时是这一层的总耗时（含所有子调用），子调用各自的耗时单独成行。所以一排 } 里最外层那个数字才是总账。
• 行首的 + / ! / # 是延迟标记，分三档：+ 表示 10us 以上、! 表示 100us 以上、# 表示 1ms 以上。实测本次采样里 + 号的最小值是 10.189us，与口径吻合。看调用树时先扫这些标记，能一眼找到慢在哪一层。

max_graph_depth 是必须理解的参数：一次普通文件读取在内核里会展开出成千上万行，因为它会一路追到页缓存、ext4、块层。本文实测把深度限制在 2 层是「信息量和可读性」的平衡点。

收窄范围：filter 与 pid 两道闸

ftrace 默认是全局的——不设限的话，你在追踪的同时，系统里每一个进程的每一次函数调用都会往缓冲区里写。实测只跟一个 sleep 进程 0.3 秒，缓冲区就写进了 39514 行。所以「先设闸、再开录」不是优化，是必需：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace
echo 'vfs_*' > set_ftrace_filter
echo "通配匹配到的函数个数: $(wc -l < set_ftrace_filter)"
echo > set_ftrace_filter

通配匹配到的函数个数: 71

set_ftrace_filter 支持三种写法：

• 通配：'vfs_*' 实测匹配 71 个函数，'ext4_*'、'tcp_*' 同理；
• 点名：vfs_read，一行一个；
• 取反：set_ftrace_notrace 是黑名单，比如把所有 rcu_* 排掉，剩下的都要。

另一道闸是 set_ftrace_pid，按进程收窄（本文前面那个 exec 技巧就是它的用法）。它接受 PID 列表，写空字符串则取消限制。这两道闸对 function 和 function_graph 都有效。

一个实操顺序上的建议：先写好 filter，再 echo function > current_tracer。反过来的话，中间那一小段时间是全量函数追踪，1 核机器上足以让你感觉「机器卡住了」。

function_profile：函数级耗时统计，以及它的口径陷阱

如果只想知道「哪个内核函数最费时间」，调用树太细了。ftrace 自带一个采样统计器：打开 function_profile_enabled，跑负载，关掉，结果在 trace_stat/function0（0 是 CPU 编号）。

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace
echo 'vfs_*' > set_ftrace_filter
echo 0 > function_profile_enabled
echo 1 > function_profile_enabled
cat /etc/hostname > /dev/null; ls /usr/bin > /dev/null
echo 0 > function_profile_enabled
head -8 trace_stat/function0

四列的含义：

• Hit：被调用的次数；
• Time：总耗时；
• Avg：平均耗时；
• s^2：方差（波动程度，越大说明耗时越不稳定）。

这张表口径必须说清楚，否则一定会误读：Time 统计的是函数从进到出在栈上的全部时间，包含它等锁、等 IO、被调度出去的时间。所以拿它当「CPU 热点」用会得到一个荒谬的榜首。实测跑一次 dd if=/dev/zero of=/dev/null bs=1M count=2000（纯内存拷贝、不碰磁盘）后，不带过滤的表长这样：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace
echo > set_ftrace_filter
echo 0 > function_profile_enabled; echo 1 > function_profile_enabled
dd if=/dev/zero of=/dev/null bs=1M count=2000 2>/dev/null
echo 0 > function_profile_enabled
head -6 trace_stat/function0

  Function                               Hit    Time            Avg             s^2
  --------                               ---    ----            ---             ---
  schedule                                13    364726.4 us     28055.87 us     9175933994 us
  __x64_sys_wait4                          2    346826.8 us     173413.4 us     60143336666 us
  kernel_wait4                             2    346826.0 us     173413.0 us     60143137936 us
  do_wait                                  2    346823.6 us     173411.8 us     60142480361 us
  __x64_sys_read                        2098    335036.8 us     159.693 us      6826.833 us

榜首是 schedule（进程被调度出去的时间）和 wait4（shell 在等子进程），而真正干活的 read_zero 排在后面。这不是 bug，是口径：想知道「CPU 时间花在哪」该用 perf，ftrace 的统计器擅长的是「调用关系与次数」。

所以更实用的读法是按 Hit 排序——它回答的是「谁被调用得最频繁」，这个信息不会被阻塞时间污染：

sort -k2 -nr /sys/kernel/tracing/trace_stat/function0 | head -8

  __cond_resched                      514352    76916.45 us     0.149 us        0.332 us
  rcu_all_qs                          514346    26449.00 us     0.051 us        0.078 us
  __clear_user                        512003    159800.1 us     0.312 us        0.639 us
  clear_user                          512002    208869.3 us     0.407 us        0.727 us
  rcu_read_unlock_strict               11903    627.413 us      0.052 us        0.007 us

__cond_resched 五十多万次、clear_user 五十多万次——这正是那次 dd 负载在内核里留下的指纹（每读 1 MB 就清零一次用户缓冲区）。同一份数据，换个排序就是另一个故事，这也是为什么这类工具必须先把口径写清楚。

再补一句上面的 set_ftrace_filter：它同样作用于统计器。截图里之所以只有 5 行 vfs_*，就是因为统计范围被收窄到了这一个函数家族——表越小，越容易看出东西。

事件：tracepoint 与 kprobe 是另一条线

调用树和统计器看的是「函数」，但内核里还有一类更结构化、更稳定的观测点：事件。它分成两种来源。

一是内核预埋的 tracepoint，实测这台机器上有 103 个子系统、其中系统调用事件 686 个：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace
echo 'prev_comm == "python3"' > events/sched/sched_switch/filter
echo 1 > events/sched/sched_switch/enable
echo 1 > tracing_on
python3 -c "
t=0
for i in range(300000): t+=i"
echo 0 > tracing_on
grep -v '^#' trace | head -3
echo 0 > events/sched/sched_switch/enable; echo 0 > events/sched/sched_switch/filter

         python3-184338  [000] d.... 1407981.732294: sched_switch: prev_comm=python3 prev_pid=184338 prev_prio=120 prev_state=R ==> next_comm=rcu_sched next_pid=13 next_prio=120
         python3-184338  [000] d.... 1407981.736317: sched_switch: prev_comm=python3 prev_pid=184338 prev_prio=120 prev_state=R ==> next_comm=kcompactd0 next_pid=24 next_prio=120
         python3-184338  [000] d.... 1407981.740319: sched_switch: prev_comm=python3 prev_pid=184338  prev_prio=120 prev_state=R ==> next_comm=rcu_sched next_pid=13 next_prio=120

事件行的格式和函数行不同：前面是「进程名-PID + CPU + 标志位 + 时间戳（秒.微秒）」，冒号后面才是事件自己的字段。这里的 filter 用的是事件字段表达式（prev_comm == "python3"），和 set_ftrace_filter 的函数名过滤是两套语法——事件过滤器支持 ==、!=、>、&&、||，能写出「只关心丢包事件里长度大于 1000 的包」这种条件。

0.15 秒的 CPU 循环被收敛成 9 行，这就是过滤器的价值：不过滤的话 sched_switch 是全系统最吵的事件之一。

二是 kprobe 动态事件——不用改内核、不用写模块，直接给任意内核函数挂探针，还能取参数：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo > trace
echo 'p:vfsread vfs_read buf=%si count=%dx' >> kprobe_events
echo 'r:vfsret vfs_read ret=$retval' >> kprobe_events
echo 'comm == "cat"' > events/kprobes/vfsread/filter
echo 'comm == "cat"' > events/kprobes/vfsret/filter
echo 1 > events/kprobes/vfsread/enable; echo 1 > events/kprobes/vfsret/enable
echo 1 > tracing_on; cat /etc/hostname > /dev/null; echo 0 > tracing_on
grep -v '^#' trace | head -6

拆解这两行定义：

• p:vfsread vfs_read buf=%si count=%dx：p: 表示入口探针，vfsread 是自定义事件名，vfs_read 是目标函数，后面是「参数名=取法」。x86_64 上函数参数按 rdi、rsi、rdx、rcx 的顺序传，vfs_read(file, buf, count, pos) 的第 2、3 个参数就落在 %si 和 %dx 上。
• r:vfsret vfs_read ret=$retval：r: 表示返回探针，$retval 是返回值。

输出里还能看到一件很有用的事：事件行会标注调用者——(ksys_read+0x67/0xe0 <- vfs_read) 里的 <- vfs_read 说明这次调用是从 ksys_read 进来的，而 (__x64_sys_pread64+0x92/0xc0 <- vfs_read) 则来自另一个入口。同一个 vfs_read，两条不同的调用路径，一眼可分。

收尾有个实测的坑：kprobe_events 不能直接清空，探针处于 enable 状态时 echo > kprobe_events 会报 Device or resource busy。正确顺序是先关事件、再清：

cd /sys/kernel/tracing
for e in events/kprobes/*/enable; do echo 0 > $e; done
echo > kprobe_events
echo "剩余 kprobe 定义: $(grep -c . kprobe_events)"

剩余 kprobe 定义: 0

清理、坑与边界

一段追踪做完，把它恢复成干净的默认状态——这一步别省，留着 tracer 开着会让机器一直背着开销：

cd /sys/kernel/tracing
echo 0 > tracing_on; echo nop > current_tracer; echo > trace
echo > set_ftrace_filter; echo > set_graph_function; echo > set_ftrace_pid
echo "tracer=$(cat current_tracer) 缓冲区行数=$(grep -vc '^#' trace)"

tracer=nop 缓冲区行数=0

三个排错入口：

1. 函数名写错：实测 echo 'no_such_fn_xyz' > set_ftrace_filter 直接返回 write error: Invalid argument（rc=1），而 error_log 文件仍然是空的——网上常说的「写错函数名去 error_log 看」，实测并不成立，看命令本身的报错更快。但 error_log 并非没用：事件过滤表达式写错会记进去，实测往事件 filter 里写空字符串会留下 event filter parse error 和一行 ^ 位置指示，排查事件过滤器时它是第一现场（而这个文件是可以 echo > error_log 清空的）。
2. trace_marker 用不了：这个文件是用来让用户态程序往 trace 里打自定义标记的（配合 trace_options 里的 record-cmd 很好用）。但本文演示机实测三个打开方式全部失败——os.open(path, O_WRONLY)、加 O_APPEND、O_RDWR 都返回 Bad file descriptor，/sys/kernel/tracing 与 /sys/kernel/debug/tracing 两个挂载点表现一致。如果在你机器上也是这样，用 tracepoint 或 kprobe 事件替代即可。
3. 实例目录里没有 function_graph：ftrace 支持在 instances/<名字>/ 下开多份独立缓冲区（多个 tracer 并行）。但这台机器上实例里的 available_tracers 只有 hwlat wakeup_dl wakeup_rt wakeup function nop 六个，没有 function_graph，写进去直接 Invalid argument。要用调用树就在主实例里跑。

最后是与邻居工具的分工，这张表比背参数有用：

小结

ftrace 的全部操作，压成一句话就是：往 /sys/kernel/tracing/ 下的文本文件里写字符串，然后读 trace。

把它拆成一条可复用的路径：

1. 说清楚要问什么——调用关系（function_graph）、调用次数（function + 统计器）、还是要某个函数的具体参数（kprobe）；
2. 先设闸再开录——set_ftrace_filter 收窄函数范围、set_ftrace_pid / set_event_pid 收窄进程，两道闸至少用一道；
3. 录一个可控的小动作，别开着 tracer 干别的事；
4. 立刻 echo 0 > tracing_on 并读走 trace——环形缓冲区只有 1.4 MB，写满就覆盖；
5. 复位（nop + 清空 filter），这是给别人（也给未来的自己）留的余地。

它最大的价值不在「功能多」，而在零成本：一台 1 核 1.9G、没装任何调试工具的机器，只要有 root，就能把内核正在干什么看得清清楚楚——不用编译、不用重启、不用装包。

想把相邻的观测手段补齐，可以接着看 strace 系统调用追踪：从卡死进程到缺失文件定位（用户态那一层）和 perf 性能剖析：从 perf stat 到采样报告定位 CPU 热点（采样那一层）；内核参数与 /proc/sys 那一套见 Linux sysctl 内核参数调优：从 /proc/sys 到 sysctl.conf 永久配置；想要另一条「内核无条件通道」的思路，Linux SysRq 魔术键：从 /proc/sysrq-trigger 到卡死进程取证 是同一个内核、另一种打开方式。