内核调试秘籍

作者 by adtxl / 2022-07-06 / 暂无评论 / 259 个足迹

转载整理自《奔跑吧 Linux内核》,张天飞著

1. printk

printk是内核中最简单最有效的调试方法。printk是内核提供的格式化打印函数,它和C库所提供的printf()函数类似。printk函数和printf函数的一个重要区别是前者提供打印等级,内核根据这个等级判断是否在终端或者串口中打印输出。

// include/linux/kern_levels.h

#define KERN_EMERG  KERN_SOH "0"    /* system is unusable */
#define KERN_ALERT  KERN_SOH "1"    /* action must be taken immediately */
#define KERN_CRIT   KERN_SOH "2"    /* critical conditions */
#define KERN_ERR    KERN_SOH "3"    /* error conditions */
#define KERN_WARNING    KERN_SOH "4"    /* warning conditions */
#define KERN_NOTICE KERN_SOH "5"    /* normal but significant condition */
#define KERN_INFO   KERN_SOH "6"    /* informational */
#define KERN_DEBUG  KERN_SOH "7"    /* debug-level messages */

Linux内核为printk定义了8个打印等级,KERN_EMERG等级最高,KERN_DEBUG等级最低。在内核配置时,有一个宏来设定系统默认的打印等级CONFIG_MESSAGE_LOGLEVEL_DEFAULT,通常设置为4,即只有打印等级高于4时才会打印到终端或者串口,也就是KERN_EMERG到KERN_ERR。通常在产品开发阶段,会把系统默认等级设置到最低,以便在开发测试阶段可以暴露更多的问题和调试信息,在产品发布时再把打印等级设置为0或者4。

// defconfig
CONFIG_MESSAGE_LOGLEVEL_DEFAULT = 8 // 默认打印等级设置为8,即打开所有的打印信息

此外,还可以通过在启动内核时传递commandline给内核的方法来修改系统默认的打印等级,例如,传递loglevel=8给内核启动参数。

在系统运行时,也可以修改系统的打印等级。

# cat /proc/sys/kernel/printk
7   4   1   7

# echo 8 > /proc/sys/kernel/printk  // 打开所有的内核打印
# echo 0 > /proc/sys/kernel/printk  // 关闭所有的内核打印

上述内容分别表示控制台打印等级、默认信息打印等级、最低打印等级和默认控制台打印等级。

在实际的调试中,把函数名字(__func__)和行号(__LINE__)打印出来也是一个很好的小技巧。

printk(KERN_EMERG "figo: %s, %d", __func__, __LINE__);

需要注意printk的打印格式,否则在编译时可能出现很多的WARNING,如下表所示

数据类型 printk格式符
int %d or %x
unsigned %u or %x
long %ld or %lx
long long %lld or %llx
unsigned long long %llu or %llx
size_t %zu or %zx
ssize_t %zd or %zx
函数指针 %pf

内核还提供了一些在实际工程中会用到的有趣的打印。

  • 打印内存buffer的数据函数print_hex_dump()
  • 打印堆栈函数dump_stack()

2. 动态打印

动态打印(Dynamic Printk Debugging)时内核子系统开发者最喜欢的打印手段之一。在系统运行时,动态打印可以由系统维护者动态打开哪些内核子系统的打印,可以有选择性地打开某些模块的打印,而printk是全局的,只能设置打印等级。要使用动态打印,必须在内核配置时打开CONFIG_DYNAMIC_DEBUG宏。内核代码里使用了大量pr_debug()/dev_dbg()函数来打印信息,这些就使用了动态打印技术,另外还需要系统挂载debugfs文件系统。

动态打印在debugfs文件系统中有一个control文件节点,文件节点记录了系统中所有使用动态打印技术的文件名和路径、打印所在的行号、模块名字和要打印的语句。

# cat /sys/kernel/debug/dynamic_debug/control
......
mm/cma.c:441 [cma]cma_alloc =_ "%s(cma %p, count %zu, align %d)\012"
mm/cma.c:486 [cma]cma_alloc =_ "%s(): memory range at %p is busy, retrying\012"
mm/cma.c:509 [cma]cma_alloc =_ "%s(): returned %p\012"
mm/cma.c:531 [cma]cma_release =_ "%s(page %p)\012"
mm/cma.c:267 [cma]cma_declare_contiguous =_ "%s(size %pa, base %pa, limit %pa alignment %pa)\012"
......

例如上面的cma模块,代码路径在mm/cma.c文件,打印语句所在行号是372,所在函数是cma_alloc(),要打印的语句是"%s(cma %p, count %zu, align %d)\012".

在使用动态打印技术之前,可以先通过查询control文件获知系统有哪些动态打印语句,例如cat control | grep xxx

下面举例来说明如何使用动态打印技术。

// 打开svcsock.c文件中所有动态打印语句
# echo 'file svcsock.c +p' > /sys/kernel/debug/dynamic_debug/control

// 打开usbcore模块所有动态打印语句
# echo 'module usbcore +p' > /sys/kernel/debug/dynamic_debug/control

// 打开svc_process()函数中所有动态打印语句
# echo 'func svc_process +p' > /sys/kernel/debug/dynamic_debug/control

// 关闭svc_process()函数中所有的动态打印语句
# echo 'func svc_process -p' > /sys/kernel/debug/dynamic_debug/control

// 打开文件路径中包含usb的文件里所有的动态打印语句
# echo -n '*usb* +p' > /sys/kernel/debug/dynamic_debug/control

// 打开系统所有的动态打印语句
# echo -n '+p' > /sys/kernel/debug/dynamic_debug/control

上面是打开动态打印语句的例子,除了能打印pr_debug()/dev_dbg()函数中定义的输出外,还能打印一些额外的信息,例如函数名、行号、模块名字和线程ID等。

  • p:打开动态打印语句
  • f:打印函数名
  • l:打印行号
  • m:打印模块名字
  • t:打印线程ID

在调试一些系统启动方面的代码,例如SMP初始化、USB核心初始化等,这些代码在系统进入shell终端时已经初始化完成,因此无法及时打开动态打印语句。
这时可以在内核启动时传递参数给内核,在系统初始化时动态打开它们,这是一个实际工程中非常好用的技巧。

例如调试SMP初始化的代码,查询到ARM SMP模块有一些动态打印语句。

# cat /sys/kernel/debug/dynamic_debug/control | grep smp
arch/arm64/kernel/setup.c:143 [setup]smp_build_mpidr_hash =_ "mask of set bits %#llx\012"
arch/arm64/kernel/setup.c:183 [setup]smp_build_mpidr_hash =_ "MPIDR hash: aff0[%u] aff1[%u] aff2[%u] aff3[%u] mask[%#llx] bits[%u]\012"
arch/arm64/kernel/smp.c:507 [smp]acpi_map_gic_cpu_interface =_ "skipping disabled CPU entry with 0x%llx MPIDR\012"
arch/arm64/kernel/smp.c:654 [smp]of_parse_and_init_cpus =_ "cpu logical map 0x%llx\012"

在内核commandline中添加smp.dyndbg=+plft,不知道是这个模块没有运行,还是这个功能在使用的版本上没支持,dmesg没看到相关log,但看了下参数是加上去了,以后再研究吧。

# cat /sys/kernel/debug/dynamic_debug/control | grep smp
arch/arm64/kernel/setup.c:143 [setup]smp_build_mpidr_hash =_ "mask of set bits %#llx\012"
arch/arm64/kernel/setup.c:183 [setup]smp_build_mpidr_hash =_ "MPIDR hash: aff0[%u] aff1[%u] aff2[%u] aff3[%u] mask[%#llx] bits[%u]\012"
arch/arm64/kernel/smp.c:507 [smp]acpi_map_gic_cpu_interface =pflt "skipping disabled CPU entry with 0x%llx MPIDR\012"
arch/arm64/kernel/smp.c:654 [smp]of_parse_and_init_cpus =pflt "cpu logical map 0x%llx\012"

还可以在各个子系统的Makefile中添加ccflags来打开动态打印。

// Makefile
ccflags-y := -DDEBUG
ccflags-y += -DVERBOSE_DEBUG

3. RAM console

上面讲述了printk和动态打印技术,它们有一个明显的缺点,都需要往串口/终端等硬件设备里输出,因此有大量打印时,系统会变得很慢。在一些对时间和时序要求比较严格的地方,这些打印延迟会影响调试效果。

trace_printk使用方法和printk一样,它输出的信息会写入ftrace的循环缓存中(ring buffer),即相当于写内存,速度比写串口等硬件设备要快好几个数量级。常用的一些场景有调度器、中断和时序要求严格的驱动。

内核还提供另外一种RAM Console的技术叫pstore。pstore是使用RAM作为存储介质的一种特殊的文件系统,主要用于在系统宕机时将日志信息写到pstore中,系统重启后再把这些日志信息写入磁盘或eMMC等存储介质。

4. OOPS分析

在编写驱动程序或内核模块时,常常会显示或隐藏地对指针进行非法取值或使用不正确的指针,导致内核产生一个oops错误。当处理器在内核空间访问一个非法的指针时,因为虚拟地址到物理地址的映射关系没有建立,触发一个缺页中断,在缺页中断中因为该地址是非法的,内核无法正确地为该地址建立映射关系,因此内核触发了一个oops错误。

下面写一个简单的内核模块,来验证如何分析一个内核oops错误。

// oops_test.c

#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/init.h>

static void create_oops(void)
{
    *(int *) 0 = 0;
}

static int __init my_oops_init(void) {
    printk("oops module init \n");
    create_oops();
    return 0;
}

static void __exit my_oops_exit(void) {
    printk("goodbye\n");
}

module_init(my_oops_init);
module_exit(my_oops_exit);
MODULE_LICENSE("GPL");

按照如下的Makefile,把oops_test.c编译成内核模块。

BASEINCLUDE ?= /home/user/txl/project/qemu_kernel/work/juno/linux   # 这里要用绝对路径

oops-objs := oops_test.o

obj-m   := oops.o

all:
        $(MAKE) -C $(BASEINCLUDE) SUBDIRS=$(PWD) modules;

clean:
        $(MAKE) -C $(BASEINCLUDE) SUBDIRS=$(PWD) clean;
        rm -rf *.ko;

使用如下的编译命令

# make ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu-

编译完成后,将oops.ko放到文件系统中。然后运行,使用insmod命令加载内核模块,oops错误信息如下。

# insmod /lib/modules/oops.ko
[   26.904616] oops: loading out-of-tree module taints kernel.
[   26.909054] oops module init
[   26.909706] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000000
[   26.909884] Mem abort info:
[   26.909933]   ESR = 0x96000046
[   26.910001]   Exception class = DABT (current EL), IL = 32 bits
[   26.910080]   SET = 0, FnV = 0
[   26.910129]   EA = 0, S1PTW = 0
[   26.910183] Data abort info:
[   26.910235]   ISV = 0, ISS = 0x00000046
[   26.910290]   CM = 0, WnR = 1
[   26.910398] user pgtable: 4k pages, 48-bit VAs, pgdp = (____ptrval____)
[   26.910549] [0000000000000000] pgd=000000005ab2c003, pud=000000005ab75003, pmd=0000000000000000
[   26.910865] Internal error: Oops: 96000046 [#1] PREEMPT SMP
[   26.911043] Modules linked in: oops(O+)
[   26.911386] Process insmod (pid: 1051, stack limit = 0x(____ptrval____))
[   26.911656] CPU: 0 PID: 1051 Comm: insmod Tainted: G           O      4.19.176 #2
[   26.911795] Hardware name: linux,dummy-virt (DT)
[   26.912000] pstate: 40000005 (nZcv daif -PAN -UAO)
[   26.912376] pc : my_oops_init+0x1c/0x1000 [oops]
[   26.912483] lr : my_oops_init+0x14/0x1000 [oops]
[   26.912582] sp : ffff00000a7abb80
[   26.912642] x29: ffff00000a7abb80 x28: 0000000000000013 
[   26.912736] x27: ffff00000a7abdf0 x26: 0000000000000022 
[   26.912803] x25: 0000000000000001 x24: ffff000008eba000 
[   26.913001] x23: ffff80001cb4b900 x22: 0000000000000000 
[   26.913103] x21: ffff0000009d5000 x20: ffff000008ddd000 
[   26.913173] x19: ffff000008eba000 x18: ffffffffffffffff 
[   26.913240] x17: 0000000000000000 x16: 0000000000000000 
[   26.913337] x15: ffff000008ddd708 x14: ffff000088ec1c47 
[   26.913409] x13: ffff000008ec1c55 x12: ffff000008df5928 
[   26.913477] x11: 0000000005f5e0ff x10: ffff000008ddd970 
[   26.913570] x9 : 00000000ffffffd0 x8 : ffff000008551cc0 
[   26.913639] x7 : 0000000000000000 x6 : 00000000000000be 
[   26.913704] x5 : 0000000000000000 x4 : 0000000000000000 
[   26.913772] x3 : ffffffffffffffff x2 : b464bc6aa74cd000 
[   26.913883] x1 : 0000000000000000 x0 : 0000000000000000 
[   26.914040] Call trace:
[   26.914177]  my_oops_init+0x1c/0x1000 [oops]
[   26.914294]  do_one_initcall+0x5c/0x178
[   26.914365]  do_init_module+0x58/0x1bc
[   26.914421]  load_module+0x1ec4/0x2358
[   26.914474]  __se_sys_init_module+0x1d0/0x248
[   26.914532]  __arm64_sys_init_module+0x18/0x20
[   26.914594]  el0_svc_common.constprop.0+0x68/0x170
[   26.914655]  el0_svc_handler+0x28/0x78
[   26.914703]  el0_svc+0x8/0xc
[   26.914917] Code: 910003fd 95ff7659 d2800001 52800000 (b900003f) 
[   26.915602] ---[ end trace 3a2f3c761a2b03f1 ]---
Segmentation fault

pc指针指向出错指向的地址,另外stack也展示了出错时程序的调用关系。首先观察出错函数my_oops_init+0x1c/0x1000,其中0x1c表示指令指针在该函数第0x18字节处,该函数本身共0x1000字节。

继续分析这个问题,建设两种情况,一是有出错模块的源代码。二是没有源代码。在某些实际工作场景中。可能需要调试和分析没有源代码的oops情况。

先看有源代码的情况,通常在编译时添加在符号信息表中,下面用两种方法来分析。

(1)使用objdump工具反汇编

$ aarch64-linux-gnu-objdump -SdCg oops.o    // 使用arm64版本的objdump工具

结果如下:

oops.o:     文件格式 elf64-littleaarch64


Disassembly of section .init.text:

0000000000000000 <init_module>:
static void create_oops(void)
{
    *(int *) 0 = 0;
}

static int __init my_oops_init(void) {
   0:   a9bf7bfd        stp     x29, x30, [sp, #-16]!
    printk("oops module init \n");
   4:   90000000        adrp    x0, 0 <init_module>
   8:   91000000        add     x0, x0, #0x0
static int __init my_oops_init(void) {
   c:   910003fd        mov     x29, sp
    printk("oops module init \n"); 
  10:   94000000        bl      0 <printk>
    *(int *) 0 = 0;
  14:   d2800001        mov     x1, #0x0                        // #0 
    create_oops();
    return 0;
}
  18:   52800000        mov     w0, #0x0                        // #0 
    *(int *) 0 = 0;
  1c:   b900003f        str     wzr, [x1]
}
  20:   a8c17bfd        ldp     x29, x30, [sp], #16
  24:   d65f03c0        ret

Disassembly of section .exit.text:

0000000000000000 <cleanup_module>:

通过反汇编工具可以看出出错函数my_oops_init+0x1c/0x1000的汇编情况吗,这里把C语言和汇编语言一起显示了出来。可以看到0x14处的指令把0赋值到x1寄存器,ox1c字节处的指令是把x1寄存器的值存放到x1寄存器执行的地址中,x1寄存器的值为0,所以这里是一个写空指针的错误。

(2)使用gdb工具
可以简单地使用gdb工具,方便快捷地定位到出错的具体地方,使用gdb中的l指令加上出错函数和偏移量即可。

可能因为编译优化的关系,并没有直接定位到具体的函数中的哪一行。

(gdb) l *my_oops_init+0x1c/0x1000
0x0 is in my_oops_init (/home/user/txl/project/qemu_kernel/tmp/oops_test.c:10).
5   static void create_oops(void)
6   {
7       *(int *) 0 = 0;
8   }
9   
10  static int __init my_oops_init(void) {
11      printk("oops module init \n");
12      create_oops();
13      return 0;
14  }

如果出错的地方是内核函数,那么可以使用vmlinux文件。

下面来看没有源代码的情况。对于没有编译符号表的二进制文件,可以使用objdump工具来dump出汇编代码,例如使用aarch64-linux-gnu-objdump -d oops.o命令来dump出oops.o文件。

user@ubuntu:~/txl/project/qemu_kernel/tmp$ aarch64-linux-gnu-objdump -d oops.o

oops.o:     文件格式 elf64-littleaarch64


Disassembly of section .init.text:

0000000000000000 <init_module>:
   0:   a9bf7bfd    stp x29, x30, [sp, #-16]!
   4:   90000000    adrp    x0, 0 <init_module>
   8:   91000000    add x0, x0, #0x0
   c:   910003fd    mov x29, sp
  10:   94000000    bl  0 <printk>
  14:   d2800001    mov x1, #0x0                    // #0
  18:   52800000    mov w0, #0x0                    // #0
  1c:   b900003f    str wzr, [x1]
  20:   a8c17bfd    ldp x29, x30, [sp], #16
  24:   d65f03c0    ret

Disassembly of section .exit.text:

0000000000000000 <cleanup_module>:
   0:   a9bf7bfd    stp x29, x30, [sp, #-16]!
   4:   90000000    adrp    x0, 0 <cleanup_module>
   8:   91000000    add x0, x0, #0x0
   c:   910003fd    mov x29, sp
  10:   94000000    bl  0 <printk>
  14:   a8c17bfd    ldp x29, x30, [sp], #16
  18:   d65f03c0    ret

内核提供了一个非常好用的脚本,可以快速帮助快速定位问题,该脚本位于linux内核源代码目录的scripts/decodecode,首先把出错的log保存到一个txt文件中。

user@ubuntu:~/txl/project/qemu_kernel/kernel/common$ ./scripts/decodecode < oops.txt 
[ 26.914917] Code: 910003fd 95ff7659 d2800001 52800000 (b900003f)
All code
========
   0:   fd                      std
   1:   03 00                   add    (%rax),%eax
   3:   91                      xchg   %eax,%ecx
   4:   59                      pop    %rcx
   5:   76 ff                   jbe    0x6
   7:   95                      xchg   %eax,%ebp
   8:   01 00                   add    %eax,(%rax)
   a:*  80 d2 00                adc    $0x0,%dl     <-- trapping instruction
   d:   00 80 52 3f 00 00       add    %al,0x3f52(%rax)
  13:   b9                      .byte 0xb9

Code starting with the faulting instruction
===========================================
   0:   3f                      (bad)  
   1:   00 00                   add    %al,(%rax)
   3:   b9                      .byte 0xb9

decodecode脚本把出错的日志转换成直观有用的汇编代码,并且告知出错具体是哪个汇编语句中,这对于分析没有源代码的oops错误非常有用。

5. BUG_ON()和WARN_ON()

在内核中经常看到BUG_ON()和WARN_ON()宏,这也是内核调试常用的技巧之一。

// include/asm-generic/bug.h

#define BUG_ON(condition) do { if (unlikely(condition)) BUG(); } while (0)

#define BUG() do { \
    printk("BUG: failure at %s:%d/%s()!\n", __FILE__, __LINE__, __func__); \
    barrier_before_unreachable(); \
    panic("BUG!"); \
} while (0)

对于BUG_ON()来说,满足条件condition就会触发BUG()宏,它会使用panic()函数来主动让系统宕机。通常是一些内核的bug才会触发BUG_ON(),在实际产品中使用要小心谨慎。

WARN_ON()相对会好一点,不会触发panic()主动宕机,但会打印函数调用栈信息,提示开发者可能发生有一些不好的事情。

独特见解