1. 为什么内核调试总让人头疼,以及Ftrace到底解决了什么
搞内核开发的人都有一个共识:用户态程序出了问题,gdb 挂上去、打几个断点、看看调用栈,大部分情况都能定位。但一旦问题出在内核态,事情就完全不一样了。内核崩溃可能表现为系统直接挂死、某个进程莫名其妙变成 D 状态、网络包延迟突然飙升、文件系统写入性能断崖式下降,甚至只是 dmesg 里多了一行看起来人畜无害的 warning。这些现象背后可能涉及调度器、内存管理、锁竞争、中断处理、驱动逻辑等无数个子系统,而你又不能像调试用户态程序那样随便暂停内核——内核停了,整个机器就停了。
传统的 printk 大法当然能用,但它的局限性非常明显。第一,printk 本身有性能开销,在高频路径上插入 printk 会改变系统的时序行为,甚至让原本能复现的问题变得无法复现。第二,printk 需要重新编译内核或至少重新加载模块,迭代周期长。第三,printk 的输出是离散的,你很难从中看出函数之间的调用关系和耗时分布。第四,有些代码路径在中断上下文或原子上下文中执行,printk 可能导致睡眠或死锁。
Ftrace 就是在这个背景下成为内核开发者工具箱里不可或缺的一件利器。它的全称是 Function Tracer,最初由 Steven Rostedt 开发,后来合入主线内核,现在已经发展成一个庞大的跟踪框架,包含 function tracer、function graph tracer、事件跟踪、动态探针、触发器、快照、过滤器等一大堆功能。最关键的是,它几乎不需要你重新编译内核,通过 debugfs 或 tracefs 文件系统就能在运行时开启和配置,对系统的影响可以控制到非常小的程度。
这篇文章适合谁看?如果你正在做内核模块开发、驱动调试、性能优化,或者你只是对 Linux 内核的运行行为感到好奇,想找一个能实际动手的工具来观察内核在干什么,那 Ftrace 就是你应该掌握的东西。我不打算把这篇写成一份手册式的文档,而是按照我自己实际使用 Ftrace 排查问题的思路来组织,把踩过的坑、常用的命令、容易忽略的细节都摊开来讲。
2. Ftrace 的核心机制与设计思路拆解
2.1 编译期插桩与运行时动态替换
Ftrace 的实现依赖两个关键机制:编译期插桩和运行时动态替换。内核在编译时如果开启了CONFIG_FUNCTION_TRACER,编译器会在几乎每个函数的入口处插入一个对mcount(或__fentry__)的调用。这个调用最初只是一条 nop 指令,占几个字节,对性能几乎没有影响。当你在运行时通过 tracefs 开启 function tracer 时,内核会把那些 nop 指令动态替换成跳转到跟踪代码的指令。关闭时再替换回 nop。这个设计非常巧妙:编译期保留了跟踪能力,运行时才决定是否激活,避免了长期性能损耗。
这里有一个容易忽略的点:不是所有函数都会被插桩。标记为notrace的函数、内联函数、以及一些早期启动代码不会被跟踪。另外,如果内核编译时没有开启CONFIG_DYNAMIC_FTRACE,那就只能使用静态的 function tracer,性能开销会大很多,而且不能按需开关。所以拿到一个内核首先确认配置,这是基本功。
2.2 tracefs 与 debugfs 的关系
早期 Ftrace 的控制接口挂在 debugfs 下面,路径是/sys/kernel/debug/tracing。后来内核引入了专门的 tracefs,通常挂载在/sys/kernel/tracing。两个路径下的内容基本一致,但 tracefs 的挂载权限可以独立控制,更适合在生产环境中限制访问。很多发行版默认只挂载了 debugfs,tracefs 需要手动挂载或者通过 fstab 配置。如果你发现/sys/kernel/tracing是空的,先检查 tracefs 有没有挂上。
mount | grep -E 'tracefs|debugfs' # 如果没有 tracefs,手动挂载 mount -t tracefs nodev /sys/kernel/tracing我个人的习惯是统一用/sys/kernel/tracing,因为它的语义更清晰,而且不会和 debugfs 下其他调试接口混在一起。但如果你面对的是一个老内核(比如 4.x 以前),可能只有 debugfs 路径可用,那就用/sys/kernel/debug/tracing。
2.3 跟踪数据的环形缓冲区设计
Ftrace 的所有跟踪数据都写入一个 per-CPU 的环形缓冲区。每个 CPU 有自己的缓冲区,写入时不需要跨 CPU 锁,这是它性能高的关键原因之一。缓冲区的大小可以通过buffer_size_kb调整,默认值通常不大,在高频跟踪场景下很容易被写满。写满之后的行为取决于trace_options里的设置:默认是覆盖旧数据,也可以配置成写满即停。
环形缓冲区的存在意味着你不能把它当成一个无限大的日志文件。跟踪几秒钟的高频事件就可能产生几十兆数据,如果缓冲区只有几兆,那你看到的只是最后那一小段。所以实际使用中,要么调大缓冲区,要么配合过滤器缩小跟踪范围,要么使用trace_pipe实时读取而不是依赖trace文件的事后查看。
2.4 事件跟踪与函数跟踪的分工
Ftrace 的跟踪能力大致分两类:函数跟踪和事件跟踪。函数跟踪关注的是“哪些函数被调用了、调用顺序是什么、每个函数花了多长时间”,适合分析代码流程和性能热点。事件跟踪关注的是“内核在某个时刻发生了什么具体事件”,比如系统调用进入退出、中断触发、调度切换、内存分配、文件系统操作等。事件是内核开发者预先埋好的静态跟踪点,每个事件有明确的字段和格式,比函数跟踪的信息密度更高、语义更清晰。
实际排查问题时,我通常先用事件跟踪快速定位到可疑的子系统,然后再用函数跟踪深入看具体的调用链。两者配合使用,效率比单独用某一种高得多。
3. 核心细节解析与实操要点
3.1 确认内核配置是否支持 Ftrace
在开始之前,必须先确认当前内核编译时开启了哪些 Ftrace 相关的配置。最直接的方法是查看/boot/config-$(uname -r)或者/proc/config.gz。
# 如果 /proc/config.gz 存在 zcat /proc/config.gz | grep -E 'FTRACE|FUNCTION_TRACER|DYNAMIC_FTRACE|TRACEPOINTS' # 或者查看 /boot 下的配置文件 grep -E 'FTRACE|FUNCTION_TRACER|DYNAMIC_FTRACE|TRACEPOINTS' /boot/config-$(uname -r)必须开启的配置项包括:
| 配置项 | 作用 | 是否必须 |
|---|---|---|
| CONFIG_FTRACE | Ftrace 框架基础 | 必须 |
| CONFIG_FUNCTION_TRACER | 函数跟踪 | 必须 |
| CONFIG_DYNAMIC_FTRACE | 动态替换 nop | 强烈建议 |
| CONFIG_FUNCTION_GRAPH_TRACER | 函数图跟踪 | 按需 |
| CONFIG_TRACEPOINTS | 静态跟踪点 | 按需 |
| CONFIG_ENABLE_DEFAULT_TRACERS | 默认跟踪器 | 按需 |
| CONFIG_STACK_TRACER | 栈跟踪 | 按需 |
如果CONFIG_DYNAMIC_FTRACE没开,function tracer 一旦开启就会一直生效,没法动态关闭,性能影响会持续存在。这种情况下要么重新编译内核,要么只用事件跟踪。
3.2 可用跟踪器的查看与切换
进入 tracefs 目录后,available_tracers文件列出了当前内核支持的所有跟踪器。
cat /sys/kernel/tracing/available_tracers # 典型输出:blk function_graph wakeup_dl wakeup_rt wakeup function nopcurrent_tracer文件用于查看和设置当前激活的跟踪器。默认是nop,表示不跟踪。切换到 function tracer:
echo function > /sys/kernel/tracing/current_tracer切换到 function_graph tracer:
echo function_graph > /sys/kernel/tracing/current_tracer注意:切换跟踪器之前最好先清空缓冲区,否则新旧数据混在一起,分析起来很麻烦。清空命令是
echo > /sys/kernel/tracing/trace。
3.3 过滤器的使用是高效跟踪的关键
不加过滤地开启 function tracer,输出量会大到无法阅读。set_ftrace_filter和set_ftrace_notrace是两个核心的过滤文件。
# 只跟踪特定函数 echo 'vfs_read' > /sys/kernel/tracing/set_ftrace_filter # 跟踪某个模块的所有函数 echo ':mod:ext4' > /sys/kernel/tracing/set_ftrace_filter # 使用通配符 echo 'vfs_*' > /sys/kernel/tracing/set_ftrace_filter # 排除某些函数 echo 'schedule' > /sys/kernel/tracing/set_ftrace_notraceset_ftrace_filter支持通配符和模块名匹配,这在调试驱动时特别有用。比如你写了一个叫mydev的模块,直接echo ':mod:mydev' > set_ftrace_filter就能把所有该模块的函数都纳入跟踪范围。
对于事件跟踪,过滤是通过events/目录下的filter文件完成的。每个事件都有自己的过滤表达式语法,支持比较运算符、逻辑运算符和字段引用。
# 只跟踪 pid 为 1234 的进程产生的 sched_switch 事件 echo 'next_pid == 1234' > /sys/kernel/tracing/events/sched/sched_switch/filter3.4 trace_pipe 与 trace 的区别
trace文件是一个静态快照,读取时会把当前缓冲区的内容全部输出,但不会阻塞。trace_pipe是一个实时管道,读取时会阻塞等待新数据,适合配合cat或脚本实时消费。
# 实时查看跟踪输出 cat /sys/kernel/tracing/trace_pipe # 事后查看缓冲区内容 cat /sys/kernel/tracing/trace实际使用中,如果跟踪量很大,trace文件可能在你读取之前就被新数据覆盖了。这时候要么调大缓冲区,要么用trace_pipe实时抓取并重定向到文件。我通常的做法是先用trace_pipe抓一小段,确认跟踪配置正确后再决定是否需要长时间抓取。
4. 实操过程与核心环节实现
4.1 场景一:定位某个系统调用的内核执行路径
假设你发现某个进程调用read()系统调用后延迟很高,想看看内核里到底走了哪些函数、在哪里卡住了。第一步,找到目标进程的 PID,然后设置 function_graph tracer 并过滤到相关函数。
cd /sys/kernel/tracing # 清空并设置跟踪器 echo > trace echo function_graph > current_tracer # 设置过滤:只跟踪与 read 相关的 vfs 层函数 echo 'vfs_read' > set_ftrace_filter echo 'vfs_write' >> set_ftrace_filter # 如果知道具体文件系统,可以加上模块过滤 echo ':mod:ext4' >> set_ftrace_filter # 开启跟踪 echo 1 > tracing_on # 执行你的测试程序 # ... # 关闭跟踪 echo 0 > tracing_on # 查看结果 cat tracefunction_graph 的输出格式是缩进的调用树,每个函数后面跟着执行时间(微秒)。通过观察哪一层函数耗时最长,就能快速定位到热点。比如你可能会看到vfs_read下面ext4_file_read_iter花了 200 微秒,而其中ext4_mpage_readpages又占了 180 微秒,那问题大概率出在块层或磁盘 I/O 上。
实操心得:function_graph 的输出量比 function tracer 大得多,因为每个函数入口和出口都会记录。如果跟踪范围太宽,缓冲区瞬间就满了。建议先用 function tracer 确认目标函数确实被调用了,再切换到 function_graph 看细节。
4.2 场景二:用事件跟踪分析调度延迟
调度延迟是内核性能问题里最常见的一类。Ftrace 提供了sched_switch、sched_wakeup、sched_wakeup_new等事件,可以精确记录每次调度切换的时间戳和涉及的进程。
cd /sys/kernel/tracing # 清空并关闭所有事件 echo > trace echo 0 > events/enable # 开启调度相关事件 echo 1 > events/sched/sched_switch/enable echo 1 > events/sched/sched_wakeup/enable # 设置过滤:只关心特定进程 echo 'next_comm == "myapp"' > events/sched/sched_switch/filter # 开启跟踪 echo 1 > tracing_on # 运行测试负载 # ... echo 0 > tracing_on cat trace输出里每一行都包含时间戳、CPU 号、当前进程、被切换进来的进程、优先级等信息。通过计算sched_wakeup到sched_switch之间的时间差,就能得到唤醒延迟。如果延迟超过预期,再结合sched_stat_runtime等事件看是不是 CPU 被其他任务占满了。
4.3 场景三:用 kprobe 动态跟踪任意函数
Ftrace 的 kprobe 机制允许你在任意内核函数(甚至函数内部的某条指令)上动态插入探针,不需要重新编译内核。这对于调试没有预埋 tracepoint 的代码路径特别有用。
cd /sys/kernel/tracing # 在 vfs_read 入口插入 kprobe echo 'p:myprobe vfs_read' > kprobe_events # 查看已注册的 kprobe cat kprobe_events # 开启对应事件 echo 1 > events/kprobes/myprobe/enable # 跟踪并查看 echo 1 > tracing_on # ... 执行操作 ... echo 0 > tracing_on cat trace # 清理 echo > kprobe_eventskprobe 还支持获取函数参数和返回值。比如p:myprobe vfs_read file=$arg1 count=$arg2可以把第一个和第二个参数记录下来。返回值探针用r:前缀,可以获取$retval。这个功能在排查“某个函数到底返回了什么错误码”时非常高效。
注意:kprobe 的语法和可用参数取决于内核版本和架构。x86_64 上
$arg1到$argN对应寄存器传参,但超过一定数量的参数可能取不到。另外,在 kprobe 的处理函数里不能睡眠,也不能访问可能缺页的用户态内存,否则会导致内核崩溃。
4.4 场景四:用 trace-cmd 简化命令行操作
直接操作 tracefs 文件系统虽然灵活,但命令比较繁琐,而且容易忘记清理。trace-cmd是一个用户态工具,把常用的 Ftrace 操作封装成了更友好的命令行接口。
# 安装(以常见发行版为例) # apt install trace-cmd 或 yum install trace-cmd # 开始记录调度事件 trace-cmd record -e sched_switch -e sched_wakeup # 停止记录后查看 trace-cmd report # 只记录特定进程 trace-cmd record -P 1234 -e sched_switch # 使用 function_graph 跟踪特定函数 trace-cmd record -p function_graph -l vfs_read -l vfs_writetrace-cmd的好处是自动处理了缓冲区大小、事件启用、数据保存等细节,生成的trace.dat文件可以用trace-cmd report或kernelshark图形化工具分析。对于需要反复跟踪、对比的场景,用trace-cmd比手动操作文件系统效率高很多。
4.5 场景五:用 snapshot 保留关键时刻的现场
有时候你只关心问题发生那一瞬间的内核状态,而不是持续跟踪。Ftrace 的 snapshot 功能可以在不停止跟踪的情况下,把当前缓冲区的内容“冻结”下来。
cd /sys/kernel/tracing # 开启跟踪 echo function > current_tracer echo 1 > tracing_on # 在某个时刻触发快照 echo 1 > snapshot # 查看快照内容 cat snapshot # 继续跟踪,缓冲区不受影响这个功能在配合触发器使用时特别强大。比如你可以设置一个触发器,当某个条件满足时自动拍快照,这样就能精确捕获到问题发生的瞬间,而不需要人工干预。
5. 常见问题与排查技巧实录
5.1 开启跟踪后系统变慢甚至卡死
这是最常见的问题,原因通常有几个:跟踪范围太宽、缓冲区太小导致频繁覆盖、在中断上下文里跟踪了不该跟踪的函数。排查思路是先用最小范围的过滤器确认跟踪本身没问题,再逐步扩大范围。如果系统已经卡死,可以通过串口或 sysrq 强制关闭跟踪。
# 紧急关闭所有跟踪 echo 0 > /sys/kernel/tracing/tracing_on echo nop > /sys/kernel/tracing/current_tracer避坑技巧:在生产环境使用 Ftrace 之前,先在测试环境验证跟踪配置。特别是 function_graph tracer,它的开销比 function tracer 大一个数量级,在高负载系统上可能直接导致服务不可用。
5.2 trace 文件为空或只有表头
可能的原因包括:跟踪器没设置、tracing_on 是 0、过滤器把所有函数都排除了、缓冲区被覆盖了。按顺序检查这几个文件:
cat current_tracer cat tracing_on cat set_ftrace_filter cat buffer_size_kb如果set_ftrace_filter是空的,function tracer 会跟踪所有函数,输出量巨大但不会为空。如果过滤器设置了但匹配不到任何函数,输出就会是空的。另外,有些内核版本在tracing_on为 0 时仍然会记录部分事件,但 function tracer 不会。
5.3 kprobe 注册失败
kprobe 注册失败通常有几个原因:函数名拼写错误、函数被内联了、函数在.init段(启动后已被释放)、或者该架构不支持 kprobe。可以通过/sys/kernel/tracing/available_filter_functions查看所有可跟踪的函数名。
grep 'vfs_read' /sys/kernel/tracing/available_filter_functions如果函数不在这个列表里,说明它被内联或者标记了notrace,无法用 kprobe 跟踪。这时候可以尝试跟踪它的调用者,或者用perf probe作为替代方案。
5.4 时间戳不准确或时区不对
Ftrace 的时间戳默认是相对于跟踪开始的偏移量,单位是秒。可以通过trace_clock文件切换时钟源,比如切换到global使用系统全局时钟,或者uptime使用启动以来的时间。
cat trace_clock echo global > trace_clock如果发现时间戳和dmesg对不上,检查一下trace_clock的设置。另外,trace_options里的latency-format选项会改变时间戳的显示格式,开启后会显示相对延迟而不是绝对时间。
5.5 缓冲区大小调整后不生效
buffer_size_kb的写入是 per-CPU 的,实际总内存占用是写入值乘以 CPU 数量。如果写入失败,可能是内存不足或者权限不够。另外,某些内核版本在跟踪器激活时不允许调整缓冲区大小,需要先切回nop。
echo nop > current_tracer echo 8192 > buffer_size_kb cat buffer_size_kb5.6 常见问题速查表
| 现象 | 可能原因 | 解决方法 |
|---|---|---|
| trace 文件为空 | tracing_on 为 0 | echo 1 > tracing_on |
| 输出量太大 | 过滤器未设置 | 设置 set_ftrace_filter |
| 系统变慢 | function_graph 开销大 | 改用 function tracer 或缩小范围 |
| kprobe 注册失败 | 函数被内联 | 查看 available_filter_functions |
| 时间戳混乱 | trace_clock 设置不当 | 切换为 global 或 uptime |
| 缓冲区溢出 | buffer_size_kb 太小 | 调大缓冲区或减少跟踪范围 |
| 事件不触发 | 事件未 enable | echo 1 > events/xxx/enable |
| 过滤器不生效 | 语法错误 | 检查 filter 文件内容 |
6. 进阶技巧与组合使用思路
6.1 用触发器实现自动化跟踪
Ftrace 的触发器(trigger)功能可以在特定事件发生时自动执行动作,比如开启/关闭跟踪、拍快照、打印栈回溯等。这在捕获偶发问题时特别有用。
# 当 sched_switch 事件中 next_comm 为 myapp 时,自动开启 function tracer echo 'next_comm == "myapp"' > events/sched/sched_switch/trigger echo 'traceon' >> events/sched/sched_switch/trigger # 当条件再次满足时关闭 echo 'traceoff' >> events/sched/sched_switch/trigger触发器支持的动包括traceon、traceoff、snapshot、stacktrace、dump等。组合使用可以实现非常精细的跟踪策略,比如“只在特定进程被调度时跟踪,其他时间不跟踪”,这样既捕获了关键信息,又避免了缓冲区被无关数据淹没。
6.2 用 stacktrace 查看调用栈
在事件触发时打印调用栈,可以快速了解代码的执行路径。stacktrace触发器就是干这个的。
echo 'stacktrace' > events/sched/sched_switch/trigger开启后,每次sched_switch事件触发时都会在 trace 输出里附带一段调用栈。这对于分析“这个事件是从哪个代码路径触发的”非常直观。不过要注意,stacktrace 本身有性能开销,不适合在高频事件上长期开启。
6.3 用 hist 触发器做统计而不是逐条记录
逐条记录事件在数据量大时很难分析。Ftrace 的 hist 触发器可以对事件字段做直方图统计,直接输出聚合结果。
# 统计 sched_switch 事件中 next_comm 的分布 echo 'hist:keys=next_comm:sort=hitcount' > events/sched/sched_switch/trigger # 查看统计结果 cat events/sched/sched_switch/hist这个功能在分析“哪个进程被调度得最频繁”“哪个错误码出现得最多”这类问题时,比逐条看 trace 高效得多。hist 触发器还支持sum、avg、max、min等聚合操作,可以对时间字段做统计分析。
6.4 用 trace-cmd 配合 kernelshark 做可视化分析
kernelshark是 trace-cmd 的图形化前端,可以把跟踪数据画成时间轴,直观展示每个 CPU 上运行的进程、事件的时间分布、函数调用的嵌套关系。对于复杂的调度延迟问题,图形化展示比看文本输出高效得多。
# 记录数据 trace-cmd record -e sched_switch -e sched_wakeup -e irq # 用 kernelshark 打开 kernelshark trace.dat在 kernelshark 里可以缩放时间轴、筛选事件、查看每个事件的详细字段。我通常用它来快速定位延迟尖峰,然后再回到命令行用 Ftrace 做精细分析。
6.5 跟踪模块加载与卸载时的行为
调试内核模块时,模块的初始化和清理函数往往是问题高发区。可以用 Ftrace 跟踪模块加载过程中的函数调用。
# 跟踪模块加载相关的内核函数 echo 'do_init_module' > set_ftrace_filter echo 'load_module' >> set_ftrace_filter echo 'do_one_initcall' >> set_ftrace_filter # 开启 function_graph echo function_graph > current_tracer echo 1 > tracing_on # 加载模块 modprobe mydev echo 0 > tracing_on cat trace这样可以清楚地看到模块初始化函数被调用的顺序、每个初始化步骤的耗时、以及是否在某个环节卡住或返回错误。
7. 我个人在实际操作中的几点体会
Ftrace 最大的价值在于它把内核从一个黑盒变成了一个可以观察的系统。但工具越强大,越需要克制。我见过太多人一上来就开 function_graph 跟踪所有函数,结果系统直接卡死,或者缓冲区里全是无关数据,根本没法分析。正确的做法永远是:先明确你要回答什么问题,再选择最小的跟踪范围,用过滤器把无关信息排除掉,最后才开启跟踪。
另一个体会是,Ftrace 的输出需要结合内核源码来读。光看函数名和耗时,你只能知道“哪里慢”,但不知道“为什么慢”。只有对着源码看调用链,才能理解每个函数在做什么、为什么会被调用、耗时是否合理。所以 Ftrace 和源码阅读是分不开的,工具只是辅助,真正的分析能力来自对内核代码的理解。
还有一点,不同内核版本的 Ftrace 接口和功能有差异。比如早期版本没有 hist 触发器,tracefs 的挂载方式也不一样。在生产环境使用之前,一定要确认目标内核的文档和实际行为。Documentation/trace/目录下的文档是最权威的参考,虽然有些内容更新不及时,但比网上大部分教程靠谱得多。
最后分享一个小技巧:如果你不确定某个跟踪配置会不会导致系统卡死,可以先在虚拟机里试。用 QEMU 起一个和目标任务环境相近的内核,在里面随便折腾,确认配置没问题再上生产。这个习惯帮我避免了好几次可能的事故。