一、Linux驱动调试方法

1.1 printk

这是驱动开发中最朴实无华,同时也是最常用和有效的手段。scull 驱动的main.c第338行如下,就是使用 printk 进行调试的例子,这样的例子相信大家在阅读驱动源码时随处可见。

// printk(KERN_ALERT "wakeup by signal in process %d\n", current->pid);

printk 的功能与我们经常在应用程序中使用的 printf 是一样的,不同之处在于 printk 可以在打印字符串前面加上内核定义的宏,例如上面例子中的KERN_ALERT(注意:宏与字符串之间没有逗号)。

#define KERN_EMERG "<0>"
#define KERN_ALERT "<1>"
#define KERN_CRIT "<2>"
#define KERN_ERR "<3>"
#define KERN_WARNING "<4>"
#define KERN_NOTICE "<5>"
#define KERN_INFO "<6>"
#define KERN_DEBUG "<7>"
#define DEFAULT_CONSOLE_LOGLEVEL 7
// 这个宏是用来定义需要打印的字符串的级别。值越小,级别越高。内核中有个参数用来控制是否将printk打印的字符串输出到控制台(屏幕或者/sys/log/syslog日志文件)


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

6 4 1 7中的6表示级别高于(小于)6的消息才会被输出到控制台,4表示如果调用 printk 时没有指定消息级别(宏)则消息的级别为4,1表示接受的最高(最小)级别是1,7表示系统启动时第一个6原来的初值是7。

因此,如果你发现在控制台上看不到你程序中某些printk的输出,请使用echo 8 > /proc/sys/kernel/printk来解决。我们在复杂驱动的开发过程中,为了调试会在源码中加入成百上千的 printk 语句,而当调试完毕形成最终产品的时候必然会将这些 printk 语句删除。

最要命的是,如果我们将调试用的printk语句删除后,用户又报告我们的驱动有 bug,所以我们又不得不手工将这些上千条的 printk 语句再重新加上。所以,我们需要一种能方便地打开和关闭调试信息的手段。看看scull驱动或者leds驱动的源代码吧!

#define LEDS_DEBUG
#undef PDEBUG             /* undef it, just in case */
#ifdef LEDS_DEBUG
    #ifdef __KERNEL__
     /* This one if debugging is on, and kernel space */
        #define PDEBUG(fmt, args…) printk( KERN_EMERG "leds: " fmt, ## args)
    #else
     /* This one for user space */
        #define PDEBUG(fmt, args…) fprintf(stderr, fmt, ## args)
    #endif
#else
    #define PDEBUG(fmt, args…) /* not debugging: nothing */
#endif
#undef PDEBUGG
#define PDEBUGG(fmt, args…) /* nothing: it’s a placeholder */

这样一来,在开发驱动的过程中,如果想打印调试消息,我们就可以用PDEBUG(“address of i_cdev is %p\n”, inode->i_cdev);,如果不想看到该调试消息,就只需要简单的将PDEBUG改为PDEBUGG即可。而当我们调试完毕形成最终产品时,只需要简单地将第1行注释掉即可。

上边那一段代码中的__KERNEL__是内核中定义的宏,当我们编译内核(包括模块)时,它会被定义。当然如果你不明白代码中的##是什么意思的话,就请认真查阅一下 GCC 关于预处理部分的资料吧!如果你实在太懒不愿意去查阅的话,那就充当 VC 工程师把上面的代码 copy 到你的代码中去吧哈哈哈哈

1.2 查看 OOP 消息

OOP 意为惊讶。当你的驱动有问题,内核不惊讶才怪:嘿!小子,你干吗乱来!好吧,就让我们来看看内核是如何惊讶的~

根据faulty.c编译出faulty.ko,并insmod faulty.ko。执行echo yang >/dev/faulty,结果内核就惊讶了。内核为什么会惊讶呢?因为 faulty 驱动的 write 函数执行了*(int *)0 = 0,向内存0地址写入,这是内核绝对不会容许的。

ssize_t faulty_write (struct file *filp, const char __user *buf, size_t count,
                loff_t *pos)
{
    /* make a simple fault by dereferencing a NULL pointer */
    *(int *)0 = 0;
    return 0;
}

Unable to handle kernel NULL pointer dereference at virtual address 00000000
pgd = c3894000
[00000000] *pgd=33830031, *pte=00000000, *ppte=00000000
Internal error: Oops: 817 [#1] PREEMPT
Modules linked in: faulty scull
CPU: 0    Not tainted  (2.6.22.6 #4)
PC is at faulty_write+0×10/0×18 [faulty]
LR is at vfs_write+0xc4/0×148
pc : [<bf00608c>]    lr : [<c0088eb8>]    psr: a0000013
sp : c3871f44  ip : c3871f54  fp : c3871f50
r10: 4021765c  r9 : c3870000  r8 : 00000000
r7 : 00000004  r6 : c3871f78  r5 : 40016000  r4 : c38e5160
r3 : c3871f78  r2 : 00000004  r1 : 40016000  r0 : 00000000
Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  Segment user
Control: c000717f  Table: 33894000  DAC: 00000015
Process sh (pid: 745, stack limit = 0xc3870258)
Stack: (0xc3871f44 to 0xc3872000)
1f40:          c3871f74 c3871f54 c0088eb8 bf00608c 00000004 c38e5180 c38e5160
1f60: c3871f78 00000000 c3871fa4 c3871f78 c0088ffc c0088e04 00000000 00000000
1f80: 00000000 00000004 40016000 40215730 00000004 c002c0e4 00000000 c3871fa8
1fa0: c002bf40 c0088fc0 00000004 40016000 00000001 40016000 00000004 00000000
1fc0: 00000004 40016000 40215730 00000004 00000001 00000000 4021765c 00000000
1fe0: 00000000 bea60964 0000266c 401adb40 60000010 00000001 00000000 00000000
Backtrace:
[<bf00607c>] (faulty_write+0×0/0×18 [faulty]) from [<c0088eb8>] (vfs_write+0xc4/0×148)
[<c0088df4>] (vfs_write+0×0/0×148) from [<c0088ffc>] (sys_write+0x4c/0×74)
  r7:00000000 r6:c3871f78 r5:c38e5160 r4:c38e5180
[<c0088fb0>] (sys_write+0×0/0×74) from [<c002bf40>] (ret_fast_syscall+0×0/0x2c)
  r8:c002c0e4 r7:00000004 r6:40215730 r5:40016000 r4:00000004
Code: e1a0c00d e92dd800 e24cb004 e3a00000 (e5800000)

第9行是惊讶的原因,也就是报告出错的原因。第10-12行是 OOP 信息序号。第13行是出错时内核已加载模块。第14行是发生错误的 CPU 序号。第15-23行是发生错误的位置,以及当时 CPU 各个寄存器的值,这最有利于我们找出问题所在地。第24行是当前进程的名字及进程 ID。第25-31行是出错时栈的内容。第32-37行是栈回溯信息,可看出直到出错时的函数递进调用关系(确保CONFIG_FRAME_POINTER被定义)。第38行是出错指令及其附近指令的机器码,出错指令本身在小括号中。

反汇编faulty.koarm-linux-objdump -D faulty.ko > faulty.dis; cat faulty.dis)可以看到如下的语句如下:

0000007c <faulty_write>:
  7c:   e1a0c00d        mov     ip, sp
  80:   e92dd800        stmdb   sp!, {fp, ip, lr, pc}
  84:   e24cb004        sub     fp, ip, #4      ; 0×4
  88:   e3a00000        mov     r0, #0  ; 0×0
  8c:   e5800000        str     r0, [r0]
  90:   e89da800        ldmia   sp, {fp, sp, pc}

定位出错位置以及获取相关信息的过程:

pc : [<bf00608c>]    lr : [<c0088eb8>]    psr: a0000013
[<bf00607c>] (faulty_write+0×0/0×18 [faulty]) from [<c0088eb8>] (vfs_write+0xc4/0×148)
[<c0088df4>] (vfs_write+0×0/0×148) from [<c0088ffc>] (sys_write+0x4c/0×74)

出错代码是faulty_write函数中的第5条指令 ,即:(0xbf00608c-0xbf00607c)/4+1=5,该函数的首地址是 0xbf00607c,该函数总共6条指令 (0×18),该函数是被0xc0088eb8的前一条指令调用的(即:函数返回地址是0xc0088eb8。这一点可以从出错时 lr 的值正好等于 0xc0088eb8得到印证)。调用该函数的指令是 vfs_write 的第49条 (0xc4/4=49) 指令。

达到出错处的函数调用流程是:write(用户空间的系统调用)–> sys_write –> vfs_write –> faulty_write

OOP 消息不仅让我定位了出错的地方,更让我惊喜的是,它让我知道了一些秘密:

1、gcc中fp到底有何用处?

2、为什么gcc编译任何函数的时候,总是要把3条看上去傻傻的指令放在整个函数的最开始?

3、内核和gdb是如何知道函数调用栈顺序,并使用函数的名字而不是地址?

4、我如何才能知道各个函数入栈的内容?哈哈,我渐渐喜欢上了让内核惊讶,那就再看一次内核惊讶吧。

执行 cat /dev/faulty,内核又再一次惊讶!

Unable to handle kernel NULL pointer dereference at virtual address 0000000b
pgd = c3a88000
[0000000b] *pgd=33a79031, *pte=00000000, *ppte=00000000
Internal error: Oops: 13 [#2] PREEMPT
Modules linked in: faulty
CPU: 0    Not tainted  (2.6.22.6 #4)
PC is at vfs_read+0xe0/0×140
LR is at 0xffffffff
pc : [<c0088c84>]    lr : [<ffffffff>]    psr: 20000013
sp : c38d9f54  ip : 0000001c  fp : ffffffff
r10: 00000001  r9 : c38d8000  r8 : 00000000
r7 : 00000004  r6 : ffffffff  r5 : ffffffff  r4 : ffffffff
r3 : ffffffff  r2 : 00000000  r1 : c38d9f38  r0 : 00000004
Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  Segment user
Control: c000717f  Table: 33a88000  DAC: 00000015
Process cat (pid: 767, stack limit = 0xc38d8258)
Stack: (0xc38d9f54 to 0xc38da000)
9f40:                                              00002000 c3c105a0 c3c10580
9f60: c38d9f78 00000000 c38d9fa4 c38d9f78 c0088f88 c0088bb4 00000000 00000000
9f80: 00000000 00002000 bef07c80 00000003 00000003 c002c0e4 00000000 c38d9fa8
9fa0: c002bf40 c0088f4c 00002000 bef07c80 00000003 bef07c80 00002000 00000000
9fc0: 00002000 bef07c80 00000003 00000000 00000000 00000001 00000001 00000003
9fe0: 00000000 bef07c6c 0000266c 401adab0 60000010 00000003 00000000 00000000
Backtrace: invalid frame pointer 0xffffffff
Code: ebffff86 e3500000 e1a07000 da000015 (e594500c)
Segmentation fault

不过这次惊讶却令人大为不解。OOP 竟然说出错的地方在 vfs_read(要知道它可是大拿们千锤百炼的内核代码),这怎么可能?哈哈,万能的内核也不能追踪函数调用栈了,这是为什么?其实问题出在 faulty_read 的第43行,它导致入栈的 r4、r5、r6、fp 全部变为了 0xffffffff,ip、lr 的值未变,这样一来 faulty_read 函数能够成功返回到它的调用者—— vfs_read。但是可怜的 vfs_read(忠实的 APTCS 规则遵守者)并不知道它的 r4、r5、r6 已经被万恶的 faulty_read 改变,这样下去 vfs_read 命运就可想而知了——必死无疑!虽然内核很有能力,但缺少了正确的 fp 的帮助,它也无法追踪函数调用栈。

ssize_t faulty_read(struct file *filp, char __user *buf,
                    size_t count, loff_t *pos)
{
        int ret;
        char stack_buf[4];
        /* Let’s try a buffer overflow  */
        memset(stack_buf, 0xff, 20);
        if (count > 4)
                count = 4; /* copy 4 bytes to the user */
        ret = copy_to_user(buf, stack_buf, count);
        if (!ret)
                return count;
        return ret;
}
00000000 <faulty_read>:
   0:   e1a0c00d        mov     ip, sp
   4:   e92dd870        stmdb   sp!, {r4, r5, r6, fp, ip, lr, pc}
   8:   e24cb004        sub     fp, ip, #4      ; 0×4
   c:   e24dd004        sub     sp, sp, #4      ; 0×4,这里为stack_buf[]在栈上分配1个字的空间,局部变量ret使用寄存器存储,因此就不在栈上分配空间了
  10:   e24b501c        sub     r5, fp, #28     ; 0x1c
  14:   e1a04001        mov     r4, r1
  18:   e1a06002        mov     r6, r2
  1c:   e3a010ff        mov     r1, #255        ; 0xff
  20:   e3a02014        mov     r2, #20 ; 0×14
  24:   e1a00005        mov     r0, r5
  28:   ebfffffe        bl      28 <faulty_read+0×28>  //这里在调用memset

  78:   e89da878        ldmia   sp, {r3, r4, r5, r6, fp, sp, pc}

1.3 利用 strace

有时小问题可以通过监视程序监控用户应用程序的行为来追踪,同时监视程序也有助于建立对驱动正确工作的信心,例如,在看了它的读实现如何响应不同数量数据的读请求之后,我们能够对 scull 正在正确运行感到有信心。

有几个方法来监视用户空间程序运行。你可以运行一个调试器来单步过它的函数,增加打印语句,或者在 strace 下运行程序。这里,我们将讨论最后一个技术,因为当真正目的是检查内核代码时,它是最有用的。

strace 命令是一个有力工具,它能显示所有的用户空间程序发出的系统调用。它不仅显示调用,还以符号形式显示调用的参数和返回值。当一个系统调用失败, 错误的符号值(例如 ENOMEM)和对应的字串(Out of memory)都显示。

strace 有很多命令行选项,其中最有用的是:

-t 来显示每个调用执行的时间,

-T 来显示调用中花费的时间,

-e 来限制被跟踪调用的类型(例如strace –eread,write ls表示只监控read和write调用),

-o 来重定向输出到一个文件(缺省情况下,strace 打印调用信息到 stderr)

strace 从内核自身获取信息。这意味着可以跟踪一个程序,不管它是否带有调试支持编译(对 gcc 是 -g 选项)以及不管它是否被 strip 过。此外,你也可以追踪一个正在运行中的进程,这类似于调试器连接到一个运行中的进程并控制它。

跟踪信息常用来支持发给应用程序开发者的故障报告,但是对内核程序员也是很有价值的。我们已经看到驱动代码运行如何响应系统调用,strace 允许我们检查每个调用的输入和输出数据的一致性。

例如,运行命令strace ls /dev > /dev/scull0将会在屏幕上显示如下的内容:

open("/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 3
fstat64(3, {st_mode=S_IFDIR|0755, st_size=24576, …}) = 0
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
getdents64(3, /* 141 entries */, 4096) = 4088
[...]
getdents64(3, /* 0 entries */, 4096) = 0
close(3) = 0
[...]
fstat64(1, {st_mode=S_IFCHR|0664, st_rdev=makedev(254, 0), …}) = 0
write(1, "MAKEDEV\nadmmidi0\nadmmidi1\nadmmid"…, 4096) = 4000
write(1, "b\nptywc\nptywd\nptywe\nptywf\nptyx0\n"…, 96) = 96
write(1, "b\nptyxc\nptyxd\nptyxe\nptyxf\nptyy0\n"…, 4096) = 3904
write(1, "s17\nvcs18\nvcs19\nvcs2\nvcs20\nvcs21"…, 192) = 192
write(1, "\nvcs47\nvcs48\nvcs49\nvcs5\nvcs50\nvc"…, 673) = 673
close(1) = 0
exit_group(0) = ?

从第一个 write 调用看,明显地,在 ls 结束查看目标目录后,它试图写 4KB。但奇怪的是,只有 4000 字节被成功写入,并且操作被重复。但当我们查看 scull 中的写实现,发现它一次最多只允许写一个 quantum(共4000字节),可见驱动本来就是期望部分写。几步之后,所有东西清空,程序成功退出。正是通过 strace 的输出,使我们确信驱动的部分写功能运行正确。

作为另一个例子,让我们读取 scull 设备(使用wc scull0命令):

[...]
open("/dev/scull0", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFCHR|0664, st_rdev=makedev(254, 0), …}) = 0
read(3, "MAKEDEV\nadmmidi0\nadmmidi1\nadmmid"…, 16384) = 4000
read(3, "b\nptywc\nptywd\nptywe\nptywf\nptyx0\n"…, 16384) = 4000
read(3, "s17\nvcs18\nvcs19\nvcs2\nvcs20\nvcs21"…, 16384) = 865
read(3, "", 16384) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), …}) = 0
write(1, "8865 /dev/scull0\n", 17) = 17
close(3) = 0
exit_group(0) = ?

如同期望的,read 一次只能获取 4000 字节,但是数据总量等同于前个例子写入的。

这个例子,意外的收获是:可以肯定,wc 为快速读进行了优化,它因此绕过了标准库(没有使用 fscanf),而是直接一个系统调用以读取更多数据。这一点,可从跟踪到的读的行里看到 wc 一次试图读取16KB的数据而确认。

  

最后修改:2023 年 07 月 29 日
如果觉得我的文章对你有用,请随意赞赏