ftrace 实战：怎么查看长延时内核函数？
ftrace 实战：怎么查看长延时内核函数？
实验环境：Ubuntu 24.04 / 内核 6.8.0-106-generic / Cgroup v2 / 华为云 FlexusX 8C16G
本文所有命令输出均来自真实实验机，可直接复现。
一、引子：用户态很快，但"卡"在内核里
perf 能告诉我们"CPU 时间烧在哪个函数"。但有时候你遇到的是另一种问题：单次系统调用偶尔慢了几毫秒，或者"某个内核函数调用链特别深、耗时异常"。这类带调用链 + 带耗时的微观分析，perf 不够细——它采样、看不到完整函数嵌套。
这时候该请出ftrace：Linux 内核自带的跟踪框架，能零采样、全量记录某个（或某类）内核函数的进入/退出、调用子链、每个子函数的耗时，还能动态插桩任意内核函数。本文用真实输出，把function_graph/tracepoint/kprobe三件套跑通，并讲清它们和 perf 的分工。
注：ftrace 接口位于
/sys/kernel/tracing（旧版在/sys/kernel/debug/tracing）。所有写操作需 root；本机已 root 直登。
二、function_graph：看清一次系统调用的内核调用链与耗时
function_graphtracer 会记录函数的进入与返回，并自动缩进出调用树，标注每个函数的耗时。我们以vfs_read（所有读文件的系统调用都会落到它）为例。
2.1 实操
root@ecs-a8bb-0002:~# T=/sys/kernel/tracing; cd $Troot@ecs-a8bb-0002:~# echo nop > current_tracerroot@ecs-a8bb-0002:~# echo 0 > tracing_onroot@ecs-a8bb-0002:~# echo > trace # 清空缓冲root@ecs-a8bb-0002:~# echo vfs_read > set_graph_function # 只展开 vfs_read 这棵子树root@ecs-a8bb-0002:~# echo function_graph > current_tracerroot@ecs-a8bb-0002:~# echo 1 > tracing_onroot@ecs-a8bb-0002:~# cat /etc/hostname >/dev/null # 触发一次 read 系统调用root@ecs-a8bb-0002:~# echo 0 > tracing_onroot@ecs-a8bb-0002:~# cat trace | head -552.2 真实输出（节选）
# tracer: function_graph # CPU DURATION FUNCTION CALLS # | | | | | | | 0) | vfs_read() { 0) | rw_verify_area() { 0) | security_file_permission() { 0) 1.020 us | apparmor_file_permission(); 0) 1.660 us | } 0) 0.310 us | __fsnotify_parent(); 0) 2.940 us | } 0) | ext4_file_read_iter() { 0) | generic_file_read_iter() { 0) 3.100 us | filemap_read(); 0) 3.640 us | } 0) 4.170 us | } 0) 0.310 us | __fsnotify_parent(); 0) + 10.090 us | } <== vfs_read 总耗时 ~10us2.3 输出解读
- 左边的
|缩进就是调用嵌套关系：vfs_read调了rw_verify_area、ext4_file_read_iter；后者又调generic_file_read_iter→filemap_read（真正的页缓存读）。 - 每行末尾的
us是该函数自身（不含子函数）耗时；最外层vfs_read()右端的+ 10.090 us是整段（含子调用）总耗时。 - 一眼看出：这次读文件
vfs_read花了 ~10us，主要耗在ext4_file_read_iter → filemap_read（读页缓存）。如果是网络/磁盘文件系统，这里就会暴露底层 I/O 延迟。
长延时怎么看：
function_graph里带+（如+ 10.090 us）或超过毫秒级的就是热点路径。配合set_graph_function限定子树，buffer 不会被无关函数淹没。
三、function tracer + set_ftrace_filter：只看"谁调用了它"
如果你不想看整棵树，只想知道"哪些路径调用了vfs_read"，用functiontracer（非 graph）+set_ftrace_filter：
root@ecs-a8bb-0002:~# echo nop > current_tracer; echo > traceroot@ecs-a8bb-0002:~# echo vfs_read > set_ftrace_filterroot@ecs-a8bb-0002:~# echo function > current_tracerroot@ecs-a8bb-0002:~# echo 1 > tracing_on; cat /etc/hostname >/dev/null; echo 0 > tracing_onroot@ecs-a8bb-0002:~# grep vfs_read trace | headcat-23523[001].....2618.024778: vfs_read<-ksys_read cat-23523[001].....2618.024781: vfs_read<-__x64_sys_pread64 cat-23523[001].....2618.024783: vfs_read<-__x64_sys_pread64 cat-23523[001].....2618.025063: vfs_read<-ksys_read cat-23523[001].....2618.025068: vfs_read<-ksys_read<-ksys_read/<-__x64_sys_pread64直接告诉你调用来源：read()和pread64()系统调用都会进入vfs_read。这是快速定位"哪个系统调用路径"的利器。set_ftrace_filter支持通配，如echo vfs_* > set_ftrace_filter一次过滤一类函数。
3.1 tracing_max_latency：测"最大延迟"
function类 tracer 只记函数；要测最差延迟，用延迟型 tracer（如wakeup，测最大调度唤醒延迟）：
root@ecs-a8bb-0002:~# echo wakeup > current_tracerroot@ecs-a8bb-0002:~# echo 1 > tracing_on; stress-ng --cpu 4 --timeout 3 >/dev/null; echo 0 > tracing_onroot@ecs-a8bb-0002:~# cat tracing_max_latency19tracing_max_latency= 19（单位 ns，本机空闲时测得极小）。它的意义：记录观测窗口内出现过的最大延迟，配合trace里那段最差路径，就能定位"最长的一次卡顿发生在哪"。生产上排查偶发延迟尖刺时，先盯tracing_max_latency有没有异常抬升，再展开对应 trace。
四、tracepoint：静态桩追踪调度与系统调用
ftrace 的events/目录下挂载了内核里成百上千个静态 tracepoint（编译期埋好的钩子）。比 kprobe 更稳、开销更低。
4.1 events/sched/sched_switch：谁抢了 CPU
root@ecs-a8bb-0002:~# echo nop > current_tracer; echo > trace; echo 1 > tracing_onroot@ecs-a8bb-0002:~# echo 1 > events/sched/sched_switch/enableroot@ecs-a8bb-0002:~# stress-ng --cpu 2 --timeout 1 >/dev/nullroot@ecs-a8bb-0002:~# echo 0 > tracing_on; echo 0 > events/sched/sched_switch/enableroot@ecs-a8bb-0002:~# grep -m3 sched_switch: trace<idle>-0[000]d..2.2618.063454: sched_switch:prev_comm=swapper/0prev_pid=0prev_prio=120prev_state=R==>next_comm=bashnext_pid=23526next_prio=120bash-23522[005]d..2.2618.063496: sched_switch:prev_comm=bashprev_pid=23522prev_prio=120prev_state=S==>next_comm=swapper/5next_pid=0next_prio=120<idle>-0[007]d..2.2618.064053: sched_switch:prev_comm=swapper/7prev_pid=0prev_prio=120prev_state=R==>next_comm=rcu_preemptnext_pid=17next_prio=120每一行是一次上下文切换：prev_comm/prev_pid（让出 CPU 的进程）==>next_comm/next_pid（抢到的进程），prev_state是让出原因（R=运行态被抢占，S=主动睡眠）。排查"为什么我的进程不跑"，sched_switch 能直接看到它被谁、在什么状态挤掉了。
4.2 events/syscalls：系统调用级观测
events/syscalls/sys_enter_*系列可精确记录每次系统调用进入（参数在events/syscalls/sys_enter_openat/format里定义）。本机sys_enter_openat/sys_enter_openat2均存在，开启后cat/ls等命令的openat调用都会被记录（行格式含filename/flags等字段）。与下文的 kprobe 相比，tracepoint 是"官方埋点"，格式稳定、零风险。
五、kprobe：动态插桩任意内核函数，抓参数
tracepoint 只在"内核作者预先埋点"的地方可用。想看任意内核函数（哪怕没有 tracepoint），用kprobe——运行时动态在函数的入口（或任意偏移）插一根"探针"，抓寄存器/参数。 ftrace 通过kprobe_events接口支持它。
5.1 实操：插桩 do_sys_openat2，抓打开的文件名
do_sys_openat2(int dfd, const char __user *filename, struct open_how *how)，按 x86_64 调用约定：第 1 参dfd在%di，第 2 参filename指针在%si，第 3 参flags（open_how内）在%dx。我们用:string把用户态文件名解引用出来：
root@ecs-a8bb-0002:~# echo nop > current_tracer; echo > trace; echo 1 > tracing_onroot@ecs-a8bb-0002:~# echo 'p:myopen do_sys_openat2 dfd=%di fname=+0(%si):string flags=%cx' > kprobe_eventsroot@ecs-a8bb-0002:~# echo 1 > events/kprobes/myopen/enableroot@ecs-a8bb-0002:~# cat /etc/hostname >/dev/null; ls / >/dev/nullroot@ecs-a8bb-0002:~# echo 0 > tracing_onroot@ecs-a8bb-0002:~# grep -m6 myopen: tracecat-24020[000].....2745.260693: myopen:(do_sys_openat2+0x0/0xe0)dfd=0xffffff9cfname="/dev/null"flags=0x8241 cat-24020[000].....2745.260980: myopen:(do_sys_openat2+0x0/0xe0)dfd=0xffffff9cfname="/etc/ld.so.cache"flags=0x88000 cat-24020[000].....2745.260993: myopen:(do_sys_openat2+0x0/0xe0)dfd=0xffffff9cfname="/lib/x86_64-linux-gnu/libc.so.6"flags=0x88000 cat-24020[000].....2745.261169: myopen:(do_sys_openat2+0x0/0xe0)dfd=0xffffff9cfname=(fault)flags=0x88000 cat-24020[000].....2745.261209: myopen:(do_sys_openat2+0x0/0xe0)dfd=0xffffff9cfname="/etc/hostname"flags=0x8000 ls-24021[003].....2745.261550: myopen:(do_sys_openat2+0x0/0xe0)dfd=0xffffff9cfname="/dev/null"flags=0x8241完美抓到参数：fname="/etc/hostname"、fname="/lib/x86_64-linux-gnu/libc.so.6"等，dfd=0xffffff9c即AT_FDCWD（-100）。注意第 4 行fname=(fault)——那是一次用户态指针在探针时刻已不可解引用（典型于某些竞态/跨地址空间场景），ftrace 如实标出(fault)而不是崩。
5.2 清理探针（务必做）
root@ecs-a8bb-0002:~# echo 0 > events/kprobes/myopen/enableroot@ecs-a8bb-0002:~# echo "-:myopen" > kprobe_events # 注销探针root@ecs-a8bb-0002:~# cat kprobe_events # 空，已清理动态插桩"即插即拔"，不用重启、不用改内核，是排查"某个内核函数到底被传了什么参数"的最快手段。
六、原理：mcount/fentry 与 静态桩 vs 动态桩
6.1 ftrace 怎么做到"函数级"跟踪
内核编译时（-pg/-mfentry），每个函数入口处都插入了一条桩指令：
- 旧机制 mcount：函数开头调用
mcount()（由 ftrace 接管）。开销大（要压栈）。 - 新机制 fentry（本内核 6.8 默认）：在函数最开头（甚至
call之前）放一个call __fentry__桩，比 mcount 更早、更省。ftrace 通过改写这块指令（或利用__fentry__跳表）来"开关"跟踪。
当 tracer 开启，ftrace 把桩点重定向到自己的 handler，于是每次函数进入/返回都被记录。这就是function/function_graphtracer 的底层。
6.2 tracepoint（静态桩）vs kprobe（动态桩）
| tracepoint | kprobe | |
|---|---|---|
| 埋点方式 | 编译期静态埋入（TRACE_EVENT宏） | 运行时动态插桩 |
| 实现 | 预留钩子，开启时回调 | 把目标地址指令替换为int3断点；命中时单步执行原指令再跳转 handler（内核优化为"优化跳转"避免单步开销） |
| 位置 | 仅内核作者埋点的位置 | 任意指令地址（函数入口/偏移均可） |
| 稳定性 | 高（ABI 稳定） | 中（依赖函数名/符号，内核升级可能失效） |
| 能否抓参数 | 能（格式固定） | 能（读寄存器/内存） |
| 风险 | 极低 | 低（写错地址可能 panic，需谨慎） |
kprobe 的
int3机制：早期 kprobe 在目标地址写0xcc（int3 断点），CPU 执行到此处触发陷阱，内核 kprobe handler 接管，处理完再单步执行被替换的原指令。现代内核用"优化跳转（optprobe）"把 int3 换成无条件跳转，省去单步，性能更好。这正是上面do_sys_openat2+0x0/0xe0里0xe0表示该函数长度的由来。
七、与 perf 的分工（怎么选）
- perf：采样、低开销、看"全局热点占比"和 IPC/cache 等硬件指标；适合先定位"哪类事情最耗时"。
- ftrace function_graph：全量、看"单次调用的完整调用链 + 每级耗时"；适合定位"某次系统调用/某函数为什么慢"。
- ftrace tracepoint：稳定地观测某类事件（调度、 Syscall、网络）；适合"按事件维度统计"。
- ftrace kprobe：临时动态探查"任意内核函数被传了什么参数"；适合"参数级取证"。
一个典型排障流：先用perf发现vfs_read占比高 → 用ftrace function_graph看vfs_read内部哪段慢 → 如果怀疑"到底读了哪些文件"，上kprobe抓do_sys_openat2的filename。三者互补。
八、排查思路与最佳实践
- 先用 nop 复位、清空 trace、设 tracing_on=0，配置好 tracer/filter 后再
tracing_on=1，触发后立刻tracing_on=0——避免 buffer 被无关噪声淹没。 - 善用 set_graph_function / set_ftrace_filter 收窄范围，否则全量函数跟踪 buffer 几秒就满。
- trace 环形缓冲有限，长时间跟踪用
trace_pipe流式读出或调大buffer_size_kb。 - kprobe 用完必清理（
echo "-:name" > kprobe_events），动态插桩残留可能影响后续或极个别路径稳定性。 - 容器场景：ftrace 是宿主机全局的，会看到所有容器/进程的内核路径；要锁定某个容器，可结合
set_ftrace_pid（写容器 init 的 host PID）或配合 cgroup 过滤（部分内核支持available_filter_functions+set_event_pid）。
九、小结与思考题
小结：ftrace 通过编译期桩（fentry/mcount）实现函数级全量跟踪，function_graph给出带耗时的调用树，tracepoint是稳定的静态事件源，kprobe能动态插桩任意内核函数抓参数。它们与 perf 互补：perf 看"占比"，ftrace 看"单次调用链与耗时"。实验中我们成功用 kprobe 抓到do_sys_openat2的真实文件名参数。
思考题：
function_graph里某函数显示+ 5.200 ms，但它的每个子函数耗时加起来才 0.3ms——那 4.9ms 去哪了？（提示：调度抢占 / 不可见的中间耗时）- kprobe 和 tracepoint 都能抓
do_sys_openat2参数，生产长期监控你选哪个？为什么？ set_graph_function只设了vfs_read，但 trace 里却出现了ext4_file_read_iter——这是 filter 失效了吗？为什么？- 容器里能直接写
/sys/kernel/tracing做 ftrace 吗？需要什么权限/挂载？（提示：通常只在宿主机，需CAP_SYS_ADMIN且挂载 tracing fs）
下一篇：《eBPF 与 bpftrace：更深入地观测内核》——当 ftrace 还不够灵活（要在内核态聚合、按 cgroup 过滤、写直方图），eBPF 登场。