1. 这次内核调试要解决的问题是什么做 Linux 内核开发的人都有一个共识写模块比写应用难调试模块比写模块难十倍。用户态程序出问题gdb 一下、printf 一下、甚至直接看 core dump基本都能定位。但内核模块一崩整个系统跟着遭殃轻则 oops 日志刷屏重则直接 panic 死机连现场都保不住。这篇文章记录的是我最近一次完整的内核模块调试经历模块本身做的是文件系统层的 read/write 拦截说白了就是在 file_operations 上做文章实现一个透明加解密的原型。整个过程踩了不少坑从动态打印到崩溃现场分析从内存越界到死锁检测基本把内核调试的常用手段都过了一遍。这篇记录适合谁看如果你正在做内核模块开发、驱动开发、文件系统过滤或者对 Linux 内核的调试手段只停留在“用 printk 打日志”这个层面那这篇文章应该能帮你少走不少弯路。里面涉及的命令和配置都是我在 5.10 内核上实际验证过的照着操作就能复现不需要什么特殊的硬件QEMU 虚拟机足够。先说下这个模块的背景。我要实现的是一个“透明加密”原型思路是替换某个文件系统的 file_operations在 read 和 write 的路径上插入加解密逻辑。应用层无感知读文件的时候自动解密写文件的时候自动加密。听起来不复杂但真正动起手来问题一个接一个。最开始是模块加载就崩后来是读写文件触发 oops再后来是并发场景下死锁每次调试都是一次“崩溃-定位-修复-再崩溃”的循环。内核调试和用户态调试最大的区别在于你没有太多试错空间。用户态崩了重启进程就行内核崩了得重启机器。而且内核的运行环境和用户态完全不同中断上下文、自旋锁、内存屏障、并发访问任何一个细节没处理好崩溃现场都可能会让你一头雾水。这篇文章就是把整个过程拆开揉碎把我用到的调试方法、踩过的坑、以及最后的解决方案原原本本地记录下来。2. 调试环境准备与工具链选型2.1 为什么选 QEMU 而不是真机我的第一反应是在开发板上做调试毕竟手头有现成的硬件。但很快发现这条路行不通开发板上跑的内核默认没开启调试信息崩溃时打印的栈回溯经常是“”一堆问号根本定位不到代码行号。重新编译内核又费时间而且开发板的串口输出、内存转储这些功能都不太方便。后来我换了思路直接在 QEMU 虚拟机里调试效果反而好得多。QEMU 做内核调试有几个实打实的好处。第一崩溃恢复快系统 panic 了直接重启虚拟机几秒钟就回来不用像真机那样反复刷机等启动。第二可以自由配置内核编译选项KASAN、LOCKDEP、KMSAN 这些调试利器想开就开不用担心性能损耗影响正常使用。第三配合 gdb stub可以在内核运行的任何时刻挂上调试器查看内存、修改变量这在真机上几乎不可能做到。第四虚拟机的磁盘就是一个镜像文件随时打快照改坏了就回滚试错成本极低。我用的启动命令大致是这样的qemu-system-x86_64 -m 2G -smp 4 \ -kernel arch/x86/boot/bzImage \ -initrd initramfs.cpio.gz \ -append consolettyS0 nokaslr panic-1 ignore_loglevel \ -nographic -s几个参数要解释一下。nokaslr是关掉内核地址空间随机化这样 gdb 和反汇编时才能拿到稳定的符号地址。ignore_loglevel是让所有等级的 printk 都往串口上打不然很多调试信息会被日志级别拦掉。-s是开启 gdb server监听 1234 端口之后用 gdb vmlinux 连上去就能调试。panic-1是让内核 panic 后自动重启不用手动干预。2.2 内核编译选项的“正确打开方式”调试内核模块内核编译选项的配置至关重要。很多新手用发行版自带的内核调试信息不全出了问题只能干瞪眼。我这边自己编译内核用了一个相对精简的配置但几个关键选项必须打开缺一不可内核选项作用调试时的意义CONFIG_DEBUG_INFO生成 DWARF 调试信息addr2line、gdb 能精确定位到源码行号CONFIG_KASAN内存越界/UAF 检测内存类 bug 直接报告出错位置CONFIG_LOCKDEP死锁检测锁顺序问题在死锁发生前就能发现CONFIG_DEBUG_ATOMIC_SLEEP原子上下文睡眠检测在自旋锁/中断里调用可睡眠函数的保护CONFIG_PROVE_LOCKING锁使用规则校验和 LOCKDEP 配合使用抓锁冲突CONFIG_KALLSYMS_ALL导出所有符号地址内核函数符号、模块符号都能查到CONFIG_FRAME_POINTER保留栈帧指针栈回溯更准确特别是老版本内核CONFIG_MAGIC_SYSRQSysRq 魔术键系统卡死时还能触发操作这里特别说下 KASAN。KASAN 的原理是用影子内存记录每一块内存的访问状态然后在每次内存访问时检查。它的开销不小运行时会慢 2 到 3 倍内存占用也高所以生产环境不开但调试阶段强烈建议开。我自己在实际调试中好几个内存越界的问题都是 KASAN 直接报出来的省了不少反汇编的功夫。LOCKDEP 也值得多说一句。它是在锁操作时记录锁的获取顺序建立“锁依赖图”如果发现某个锁可以按 A-B 和 B-A 两种顺序获取就会报 possible circular locking dependency detected。这个检测发生在死锁真正发生之前等真正死锁了再去排查系统已经卡死了反而不容易定位。2.3 调试工具的适用场景——printk 并不是万能的调试工具的选择要分场景。printk 最直接适合打印关键路径上的变量和状态但问题是需要重新编译模块、重新加载调试一次要等很久。而且 printk 在多核并发下会互相穿插看日志有时候像在拼拼图。dynamic debug 可以在不重新编译的情况下动态打开或关闭某个文件的调试输出这个比 printk 灵活得多我这篇文章后面会详细说。ftrace 适合追踪函数调用关系尤其是你想知道“某个路径到底是怎么走到这里的”。kprobe 可以在任意函数入口和出口挂钩子动态修改行为甚至替换函数实现适合做深度的行为分析。gdb/kgdb 适合对某个“现场”做细致检查但需要提前规划好不然跑太快根本来不及断下来。工具选型的核心原则是从快到慢、从粗到细。先用 dynamic debug 看整体流程再用 ftrace 看调用链路然后根据现象决定要不要用 kprobe 做定点分析最后实在不行再上 gdb。我个人的经验是80% 的问题在 dynamic debug 阶段就能定位到真正需要 gdb 的其实是那些并发类的、时序类的疑难杂症。3. 第一次崩溃模块加载直接 oops3.1 崩溃现场长什么样模块写好以后我信心满满地 insmod 加载结果控制台瞬间刷出一屏东西系统直接卡死。因为开了 panic-1几秒后自动重启了。把串口日志拉出来看最后几行是这个样子的BUG: unable to handle kernel paging request at ffff9c1a12345678 PGD 1005067 P4D 1005067 PUD 0 Oops: 0002 [#1] PREEMPT SMP KASAN CPU: 2 PID: 1737 Comm: insmod Tainted: G OE 5.10.0-custom #12 RIP: 0010:cks_write0x2b/0x40 [cks_filter] Code: 48 89 e5 48 83 ec 10 48 89 7d f8 48 89 75 f0 e8 ... RSP: 0018:ffffc9000038bc58 EFLAGS: 00010246 RAX: 0000000000000000 RBX: ffff9c1a12345678 RCX: ffff9c1a567890ab RDX: 0000000000000000 RSI: ffff9c1a23456789 RDI: ffff9c1a12345678 RBP: ffffc9000038bc68 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000 R13: ffff9c1a34567890 R14: 0000000000000001 R15: 0000000000000000 Call Trace: cks_ioctl0x4e/0x80 [cks_filter] __x64_sys_ioctl0x87/0xb0 do_syscall_640x33/0x40 entry_SYSCALL_64_after_hwframe0x44/0xa9这个日志是内核 oops 时的标准格式信息量非常大。最上面一行BUG: unable to handle kernel paging request说明访问了一个非法地址fff...这样的地址一看就不是正常的物理内存映射更像是野指针或者被篡改过的指针。Oops: 0002 [#1]这里的 0002 是错误码bit 1 为 1 表示是写操作引起的缺页也就是说我的模块在向一个非法地址写数据。RIP: 0010:cks_write0x2b/0x40 [cks_filter]这一行最关键它明确告诉了我崩溃在 cks_write 这个函数偏移 0x2b函数总长度 0x40。后面的 Call Trace 是从 ioctl 调用进来的说明我的 write 函数是被 ioctl 间接调用的。这就有意思了write 函数里我没有写任何不该写的地方怎么会访问非法地址3.2 用 addr2line 和 objdump 把崩溃点翻译成人话有了 RIP 偏移量定位源码行就很容易了。模块在编译时我开了-g选项保留调试信息所以直接用 addr2line 就能翻译成源码行号addr2line -e cks_filter.ko 0x2b结果输出/home/user/cks_filter.c:45打开源码一看第 45 行是static ssize_t cks_write(struct file *filp, const char __user *buf, size_t len, loff_t *off) { struct cks_priv *priv filp-private_data; // 第 44 行 priv-write_buf buf; // 第 45 行 return len; }问题一目了然。filp-private_data是 NULL第 44 行赋值成功但第 45 行解引用的时候就崩了。我这才想起来open 的时候我分配了 private_data但测试程序用的 open 方式走的不是我的 open 函数——因为模块是在另一个设备节点上替换了 file_operations测试程序打开的却是旧的设备节点所以 private_data 一直是 NULL。这个问题的本质是file_operations 替换的时机和对象没搞对。我在做模块初始化的时候把一个特定设备的 file_operations 指针替换掉了但 ioctl 已经被其他路径打开了设备private_data 压根没有初始化。这个算是比较低级的问题但暴露了一个重要原则在 file_operations 里做任何解引用之前先判空。3.3 模块符号地址的另一种查法如果不用 addr2line也可以直接在崩溃现场查符号。模块加载后/proc/kallsyms 里能看到模块导出的符号地址但注意模块内静态函数的符号在前面的 oops 日志里可能显示不全。更可靠的方式是看 /sys/module/模块名/sections/ 下的段地址配合 objdump 反汇编一起用cat /sys/module/cks_filter/sections/.text 0xffffffffc02c0000然后 objdump 反汇编模块的 text 段从模块基址加偏移算出崩溃点对应的指令objdump -d cks_filter.ko用0xffffffffc02c0000 0x2b找到对应的反汇编代码排查是哪条指令出了错。不过这个方法比 addr2line 笨重很多应急可以日常还是用 addr2line 更高效。把这个记到问题速查表里后面会再提到。4. dynamic debug 的妙用不用重新编译就能打日志4.1 从 printk 到 dynamic debug调试效率的跃升第一次崩溃修完之后我信心满满地继续测。但很快又遇到了新问题读写文件的路径上数据有时对有时不对没有规律。这时候如果用 printk 打日志每次改一行代码都要重新编译、重新卸载模块、重新加载、重新复现一个循环下来至少几分钟。而且 printk 打多了以后日志量太大反而看不出关键信息。后来我改用内核的 dynamic debug 机制效率提升非常明显。dynamic debug 的核心思想是把调试打印语句编译进模块但默认不输出运行时通过 debugfs 动态控制哪些文件、哪些函数、甚至哪一行代码的打印开启或者关闭。不需要重新编译敲一行命令就能生效这个在实机调试时太香了。编译模块时加上-DDEBUG代码里用pr_debug()替代printk(KERN_DEBUG ...)。模块加载后执行echo file cks_filter.c p /sys/kernel/debug/dynamic_debug/control这样 cks_filter.c 里所有 pr_debug 就会开始输出。如果想只看某一个函数的输出echo func cks_write p /sys/kernel/debug/dynamic_debug/control如果需要控制台也能看到这些日志而不只是 dmesg还要把 console loglevel 调低echo 8 /proc/sys/kernel/printk4.2 格式化日志的正确姿势pr_debug 的用法和 printk 类似但有几个小技巧值得注意。第一个打印指针不要直接%p内核默认会做指针哈希显示的地址是处理过的不利于和崩溃日志里的地址对账。用%px可以显示真实地址但生产环境不建议这么干调试时可以临时用。第二个打印缓冲区内容时用%*ph可以按十六进制打印一块内存格式非常紧凑。比如要打印一个 16 字节的 keypr_debug(cks key: %*ph\n, 16, priv-key);第三个日志不能太密集。如果每次 read/write 都打日志在高频调用下 dmesg 会被瞬间刷满系统性能也会严重下降。我习惯的做法是加一个计数每 1000 次才打一次if ((priv-debug_count % 1000) 0) pr_debug(cks write count: %ld\n, priv-debug_count);这样既能观察到规律又不会把系统拖垮。4.3 实际调试中我是怎么用 dynamic debug 定位数据错乱的这次数据时对时错的问题我最后是通过 dynamic debug 定位的。我在 read 和 write 的入口、出口分别打了 pr_debug打印 file 指针、buf 指针、长度、以及加解密前后的数据指纹。因为只需要开一个文件的调试输出日志量可控性能也没受太大影响。日志出来后我惊讶地发现write 和 read 拿到的 file 指针根本不是同一个这就解释了为什么数据会错乱加密和解密操作作用在了不同的文件对象上解密时拿到的 key 和加密时不一致。问题根源是设备节点的 file_operations 替换覆盖了多个 inode但对应的 private_data 是通过不同路径设置的open 时有的路径没有执行到我的初始化代码。修改了 open 函数的替换逻辑保证所有入口都会走同一条初始化路径问题迎刃而解。说实话这种问题如果还用 printk 盲打可能要折腾好几个小时dynamic debug 把定位时间压缩到了十几分钟。5. 内存越界和死锁两个最头疼的问题5.1 KASAN 是怎么帮我抓到越界写入的数据错乱问题解决之后我继续压测。在持续读写文件并配合多线程并发访问的情况下系统在运行 10 分钟左右后再次出现异常。这次没有 oops而是 KASAN 直接报了一段长长的错误报告BUG: KASAN: slab-out-of-bounds in cks_read0x9c/0x120 [cks_filter] Write of size 4 at addr ffff888036404010 by task kworker/u4:2 CPU: 1 PID: 1739 Comm: kworker/u4:2 Tainted: G OE 5.10.0-custom #12 ... Memory state around the buggy address: ffff888036403f00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ffff888036403f80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ffff888036404000: 00 00 00 fc fc fc fc fc fc fc fc fc fc fc fc fc看到slab-out-of-bounds我就明白了这是访问了 slab 对象边界外的内存。Write of size 4说明发生了 4 字节的写操作目标在内核堆的末尾。Memory state around这一段是 KASAN 的经典输出fc fc表示红色区redzone正常情况下写到这里就是越界。我的模块在 cks_read 里往一个缓冲区写数据但缓冲区大小估计错了多写了 4 个字节。找到问题代码static ssize_t cks_read(struct file *filp, char __user *buf, size_t len, loff_t *off) { char tmp[4096]; ... memcpy(tmp len, priv-tag, 4); // 这里 len 可能等于 4096越界写 4 字节 ... }tmp 数组只有 4096 字节如果 len 等于 4096那tmp 4096就指向数组之外再写 4 字节就是越界。修复方式很简单把数组改成char tmp[4100]或者先判 len 的边界。KASAN 的威力在于它不仅能告诉你“崩了”还能告诉你“快崩了”在越界发生的瞬间就抓到了。5.2 LOCKDEP 提前暴露的锁顺序问题内存问题解决后我继续压测。这次更隐蔽系统没有崩溃而是“卡住”了。某个线程执行的 ioctl 长时间不返回top 显示 CPU 占用接近 100%但业务线程全部阻塞。我一开始怀疑是死循环但 strace 挂在目标进程上没看到任何系统调用返回像是内核态卡死了。正当我准备用 sysrq 做 crash dump 的时候我注意到 dmesg 里有一段被淹没的警告 WARNING: possible circular locking dependency detected ------------------------------------------------------ 5.10.0-custom #12 Tainted: G OE is trying to acquire lock: ffff8880359d3d28 ((priv-lock)-rlock){....}-{2:2}, at: cks_write0x46/0x100 [cks_filter] but task is already holding lock: ffff8880364bf2a0 (f-f_lock){....}-{2:2}, at: cks_ioctl0x1a/0x80 [cks_filter] which lock was already held when task acquired lock: ffff8880364bf2a0 (f-f_lock){....}-{2:2}, at: cks_ioctl0x1a/0x80 [cks_filter]LOCKDEP 检测到了可能的环形锁依赖。我的代码在 ioctl 里先持有了 file 结构体的锁f_lock然后在 write 里又尝试获取自己的锁priv-lock而另外一条路径是先拿 priv-lock再拿 f_lock。两个路径的锁顺序相反当两个线程同时执行时就可能死锁。这种死锁最坑的地方在于它不会每次必现只在特定调度顺序下出现可能压测几个小时才触发一次。如果不用 LOCKDEP我根本不知道锁顺序有问题。修复方式有两种一是统一锁获取顺序二是缩小锁范围不要在持有 f_lock 的情况下再拿 priv-lock。我选了第二种把 ioctl 里需要持锁的代码拆开避免锁嵌套。5.3 并发问题的另一种调试视角ftrace 看时序死锁问题让我对并发场景格外敏感后续又做了一轮并发压测这次没有出现死锁但出现了读写数据不一致的情况。速度很快的并发读写时不时读出来的数据是“旧”的。我怀疑是加解密操作的原子性问题写入方在写的过程中读取方已经读走了半个加密块。这种问题用 LOCKDEP 看不到因为它不是锁的问题而是临界区覆盖范围的问题。我用了 ftrace 来追踪读写路径的执行时序。ftrace 使用很简单cd /sys/kernel/debug/tracing echo function_graph current_tracer echo cks_write set_graph_function echo cks_read set_graph_function echo 1 tracing_on cat traceftrace 会输出 cks_write 和 cks_read 的调用栈以及执行时长。看完 trace 我确认了自己的猜测write 还没写完整个块read 就已经开始读了中间没有任何同步。修复方案是在读写路径上加读写锁保证同一时刻只有一个方向的加解密操作在进行。这里有个经验之谈很多并发 bug 的表现形式千奇百怪有卡死、有数据错乱、有偶发 oops但根因往往是同一个——临界区没保护到位。排查并发问题不要把目光只盯着“出错的那行代码”要往前看看看是哪个共享资源没有被正确同步。6. 崩溃现场的无损恢复pstore 和串口的配合6.1 没开 KASAN 的崩溃怎么查有一次我偷懒想看看模块在不开 KASAN、接近生产配置的情况下表现如何。结果不出意外压测又崩了。这次没有 KASAN 帮忙只有一段 oops而且因为开启了 KASLRRIP 显示的地址不是真实物理地址addr2line 直接失效。这时候就体现出配置的重要性了。如果当时不开 KASLR或者把/proc/kallsyms里的符号表抄下来还能对地址。但真正可复现的办法是利用 pstore/ramoops。pstore 会把内核崩溃前的最后一段日志保存到一块独立的内存区域重启后并不会丢失这样即使系统 panic 自动重启了也能从 dmesg 里找回崩溃现场。我的内核配置里开了 CONFIG_PSTORE、CONFIG_PSTORE_RAM、CONFIG_PSTORE_CONSOLE然后挂载 pstore 文件系统mount -t pstore pstore /sys/fs/pstore ls /sys/fs/pstore/崩溃后重启/sys/fs/pstore/ 下会有 dmesg-ramoops-0 这样的文件里面就是上一次崩溃前最后打印的日志。这个方法在真机上特别有用虚拟机上反而不如直接看串口方便。6.2 截图和录屏是调试者的“后悔药”除了 pstore我还习惯在 QEMU 启动时加一个-serial file:serial.log参数把串口输出重定向到文件。这样即使控制台界面被刷没了串口日志也是完整的。串口日志配合 QEMU 的 QMP 接口还能做更多高级操作比如在崩溃瞬间执行pmemsave把物理内存导出来做离线分析。这个方法我调试内存泄漏时用过效果很好但操作步骤比较繁琐一般问题用不到这个级别。调试内核崩溃时最怕的是“没留下任何痕迹”。所以我的习惯是不管做什么实验先把日志保存机制打开。真机上用 pstore虚拟机上用串口文件双保险。你永远不知道下一次崩溃会什么时候来但只要有日志就有定位的希望。7. 常见问题速查表与避坑清单这部分把我这次调试过程中遇到的和总结到的高频问题整理成一个速查表以后排查类似问题直接照着查。症状可能原因排查方法insmod 失败提示 Unknown symbol模块依赖的符号未导出查看 /proc/kallsyms 确认符号是否存在检查 EXPORT_SYMBOLprintk 打印看不到loglevel 太高echo 8 /proc/sys/kernel/printk或启动参数加 ignore_logleveloops 里 RIP 显示为 ? 或地址对应不上源码没有调试信息或 KASLR 开启编译加 -g、加载时加 nokaslr系统随机崩溃但 dmesg 没有 oops可能是硬件问题或内存损坏查 /var/log/messages、跑 memtest检查温度崩溃后重启找不到日志没有开启 pstore/ramoops挂载 pstore检查 /sys/fs/pstoreKASAN 报 slab-out-of-bounds数组越界或缓冲区大小计算错误检查 memcpy 的目标大小确认边界条件LOCKDEP 报 circular locking锁获取顺序不一致统一锁顺序减少锁嵌套模块卸载时报 Modules linked in 错误有资源未释放检查 exit 函数是否完整kmemleak 排查泄漏ftrace 输出为空权限或追踪器配置错误确认 root 权限tracing_on 是否打开addr2line 定位不对模块重定位导致偏移计算错误用 compile 时保留的 .text 段地址计算避坑清单更具体是每次调试都值得对照一下的改完代码先看编译警告。内核代码的编译警告往往意味着问题不要忽略 -Wunused、-Wformat 这类告警很多越界就是参数类型不匹配埋的雷。模块加载前先备好崩溃恢复手段。至少保证串口能输出日志虚拟机能随时回滚快照。一次只改一个变量。我见过太多人一口气改了十几个地方然后崩溃了不知道是哪个改动引起的排查成本翻了好几倍。模块里的打印用 pr_debug 而不是 printk。这样调试信息可以动态开关不会污染正常日志。oops 日志第一行和 Call Trace 最重要。不要去读中间那些 CPU 寄存器值先看 RIP 和 Call Trace能解决 80% 的问题。保持模块小而单一。我见过一个模块几千行各种功能杂糅在一起光是找到崩溃点就要半天。功能拆开一个模块只干一件事调试幸福感直线上升。8. 最后分享一点个人体会做了这么久的内核调试最大的感受是调试内核模块其实不是在调试“代码”而是在调试“运行环境”。用户态程序错了你可以在入口打断点一步步看内核模块错了很多时候系统已经处在半瘫痪状态你能依赖的只有那一段日志。所以内核调试的本质是“从现象反推原因”日志、栈回溯、反汇编都是反推的线索。工具上我觉得最划算的投资就是提前把内核编译选项配好。KASAN、LOCKDEP、DEBUG_INFO 这些选项开起来看起来浪费了一点性能但实际上帮你省下的调试时间远远超过编译时间。如果没有这些调试工具我这次遇到的内存越界和死锁问题估计要花几倍的时间才能定位。还有一个建议是养成记录调试过程的习惯。这个项目最后的调试笔记我整理成了 markdown按“问题现象-排查过程-根因-修复-验证”的结构写。一段时间后回看很多当时觉得惊天动地的 bug其实都是很典型的模式。记录多了以后再遇到类似问题脑子里能直接浮现出“这个问题上次见过大概是哪个方向”。内核调试这条路没有捷径但每解决一个问题你对系统运行机制的理解就会加深一层。希望这篇记录能给你一些参考让你在下一次面对内核崩溃的时候少一点慌乱多一点从容。