行业资讯
ftrace 实战：怎么查看长延时内核函数？
ftrace 实战怎么查看长延时内核函数实验环境Ubuntu 24.04 / 内核 6.8.0-106-generic / Cgroup v2 / 华为云 FlexusX 8C16G本文所有命令输出均来自真实实验机可直接复现。一、引子用户态很快但卡在内核里perf 能告诉我们CPU 时间烧在哪个函数。但有时候你遇到的是另一种问题单次系统调用偶尔慢了几毫秒或者某个内核函数调用链特别深、耗时异常。这类带调用链 带耗时的微观分析perf 不够细——它采样、看不到完整函数嵌套。这时候该请出ftraceLinux 内核自带的跟踪框架能零采样、全量记录某个或某类内核函数的进入/退出、调用子链、每个子函数的耗时还能动态插桩任意内核函数。本文用真实输出把function_graph/tracepoint/kprobe三件套跑通并讲清它们和 perf 的分工。注ftrace 接口位于/sys/kernel/tracing旧版在/sys/kernel/debug/tracing。所有写操作需 root本机已 root 直登。二、function_graph看清一次系统调用的内核调用链与耗时function_graphtracer 会记录函数的进入与返回并自动缩进出调用树标注每个函数的耗时。我们以vfs_read所有读文件的系统调用都会落到它为例。2.1 实操rootecs-a8bb-0002:~# T/sys/kernel/tracing; cd $Trootecs-a8bb-0002:~# echo nop current_tracerrootecs-a8bb-0002:~# echo 0 tracing_onrootecs-a8bb-0002:~# echo trace # 清空缓冲rootecs-a8bb-0002:~# echo vfs_read set_graph_function # 只展开 vfs_read 这棵子树rootecs-a8bb-0002:~# echo function_graph current_tracerrootecs-a8bb-0002:~# echo 1 tracing_onrootecs-a8bb-0002:~# cat /etc/hostname /dev/null # 触发一次 read 系统调用rootecs-a8bb-0002:~# echo 0 tracing_onrootecs-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非 graphset_ftrace_filterrootecs-a8bb-0002:~# echo nop current_tracer; echo tracerootecs-a8bb-0002:~# echo vfs_read set_ftrace_filterrootecs-a8bb-0002:~# echo function current_tracerrootecs-a8bb-0002:~# echo 1 tracing_on; cat /etc/hostname /dev/null; echo 0 tracing_onrootecs-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测最大调度唤醒延迟rootecs-a8bb-0002:~# echo wakeup current_tracerrootecs-a8bb-0002:~# echo 1 tracing_on; stress-ng --cpu 4 --timeout 3 /dev/null; echo 0 tracing_onrootecs-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谁抢了 CPUrootecs-a8bb-0002:~# echo nop current_tracer; echo trace; echo 1 tracing_onrootecs-a8bb-0002:~# echo 1 events/sched/sched_switch/enablerootecs-a8bb-0002:~# stress-ng --cpu 2 --timeout 1 /dev/nullrootecs-a8bb-0002:~# echo 0 tracing_on; echo 0 events/sched/sched_switch/enablerootecs-a8bb-0002:~# grep -m3 sched_switch: traceidle-0[000]d..2.2618.063454: sched_switch:prev_commswapper/0prev_pid0prev_prio120prev_stateRnext_commbashnext_pid23526next_prio120bash-23522[005]d..2.2618.063496: sched_switch:prev_commbashprev_pid23522prev_prio120prev_stateSnext_commswapper/5next_pid0next_prio120idle-0[007]d..2.2618.064053: sched_switch:prev_commswapper/7prev_pid0prev_prio120prev_stateRnext_commrcu_preemptnext_pid17next_prio120每一行是一次上下文切换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 参flagsopen_how内在%dx。我们用:string把用户态文件名解引用出来rootecs-a8bb-0002:~# echo nop current_tracer; echo trace; echo 1 tracing_onrootecs-a8bb-0002:~# echo p:myopen do_sys_openat2 dfd%di fname0(%si):string flags%cx kprobe_eventsrootecs-a8bb-0002:~# echo 1 events/kprobes/myopen/enablerootecs-a8bb-0002:~# cat /etc/hostname /dev/null; ls / /dev/nullrootecs-a8bb-0002:~# echo 0 tracing_onrootecs-a8bb-0002:~# grep -m6 myopen: tracecat-24020[000].....2745.260693: myopen:(do_sys_openat20x0/0xe0)dfd0xffffff9cfname/dev/nullflags0x8241 cat-24020[000].....2745.260980: myopen:(do_sys_openat20x0/0xe0)dfd0xffffff9cfname/etc/ld.so.cacheflags0x88000 cat-24020[000].....2745.260993: myopen:(do_sys_openat20x0/0xe0)dfd0xffffff9cfname/lib/x86_64-linux-gnu/libc.so.6flags0x88000 cat-24020[000].....2745.261169: myopen:(do_sys_openat20x0/0xe0)dfd0xffffff9cfname(fault)flags0x88000 cat-24020[000].....2745.261209: myopen:(do_sys_openat20x0/0xe0)dfd0xffffff9cfname/etc/hostnameflags0x8000 ls-24021[003].....2745.261550: myopen:(do_sys_openat20x0/0xe0)dfd0xffffff9cfname/dev/nullflags0x8241完美抓到参数fname/etc/hostname、fname/lib/x86_64-linux-gnu/libc.so.6等dfd0xffffff9c即AT_FDCWD-100。注意第 4 行fname(fault)——那是一次用户态指针在探针时刻已不可解引用典型于某些竞态/跨地址空间场景ftrace 如实标出(fault)而不是崩。5.2 清理探针务必做rootecs-a8bb-0002:~# echo 0 events/kprobes/myopen/enablerootecs-a8bb-0002:~# echo -:myopen kprobe_events # 注销探针rootecs-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动态桩tracepointkprobe埋点方式编译期静态埋入TRACE_EVENT宏运行时动态插桩实现预留钩子开启时回调把目标地址指令替换为int3断点命中时单步执行原指令再跳转 handler内核优化为优化跳转避免单步开销位置仅内核作者埋点的位置任意指令地址函数入口/偏移均可稳定性高ABI 稳定中依赖函数名/符号内核升级可能失效能否抓参数能格式固定能读寄存器/内存风险极低低写错地址可能 panic需谨慎kprobe 的int3机制早期 kprobe 在目标地址写0xccint3 断点CPU 执行到此处触发陷阱内核 kprobe handler 接管处理完再单步执行被替换的原指令。现代内核用优化跳转optprobe把 int3 换成无条件跳转省去单步性能更好。这正是上面do_sys_openat20x0/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_on0配置好 tracer/filter 后再tracing_on1触发后立刻tracing_on0——避免 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_functionsset_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 登场。
郑州网站建设
网页设计
企业官网
