2驱动程序调测方法与技巧

1、第二章驱动程序调测方法与技巧驱动程序开发的一个重大难点就是不易调试。本文目的就是介绍驱动开发中常用 的几种直接和间接的调试手段，它们是：利用 printk查看OOP消息利用 strace利用内核内置的hacking选项利用ioctl方法利用/proc文件系统使用kgdb一、利用 printk这是驱动开发中最朴实无华，同时也是最常用和有效的手段。scull驱动的 main.c第338行如下，就是使用printk进行调试的例子，这样的例子相信大家 在阅读驱动源码时随处可见。338 /printk（KERN_ALERT wakeup by signal in process %dn,current-

2、pid）;printk的功能与我们经常在应用程序中使用的printf是一样的，不同之处在于 printk可以在打印字符串前面加上内核定义的宏，例如上面例子中的 KERN_ALERT （注意：宏与字符串之间没有逗号）。#define KERN_EMERG #define KERN_ALERT #define KERN_CRIT #define KERN_ERR #define KERN_WARNING #define KERN_NOTICE #define KERN_INFO #define KERN_DEBUG #define DEFAULT_CONSOLE_LOGLEVEL 7这个宏是用来定

3、义需要打印的字符串的级别。值越小，级别越高。内核中有个参 数用来控制是否将printk打印的字符串输出到控制台（屏幕或者 /sys/log/syslog 日志文件）# cat /proc/sys/kernel/printk417第一个6表示级别高于(小于)6的消息才会被输出到控制台，第二个4表示如 果调用printk时没有指定消息级别(宏)则消息的级别为4,第三个1表示接 受的最高(最小)级别是1，第四个7表示系统启动时第一个6原来的初值是7。因此，如果你发现在控制台上看不到你程序中某些printk的输出，请使用echo 8 /proc/sys/kernel/printk 来解决。我们在复杂驱

4、动的开发过程中，为了调试会在源码中加入成百上千的printk语 句。而当调试完毕形成最终产品的时候必然会将这些printk语句删除(为什么？ 想想你自己是驱动的使用者而不是开发者吧。记住：己所不欲，勿施于人)，这 个工作量是不小的。最要命的是，如果我们将调试用的printk语句删除后，用 户又报告我们的驱动有bug，所以我们又不得不手工将这些上千条的printk语 句再重新加上。oh，my god，杀了我吧。所以，我们需要一种能方便地打开和关 闭调试信息的手段。哪里能找到这种手段呢？哈哈，远在天边，近在眼前。看看 scull驱动或者leds驱动的源代码吧！#define LEDS_DEBUG#

5、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 PDEBU

6、G(fmt, args.) /* not debugging: nothing */#endif#undef PDEBUGG#define PDEBUGG(fmt, args.) /* nothing: its a placeholder */这样一来，在开发驱动的过程中，如果想打印调试消息，我们就可以用PDEBUG(address of i_cdev is %pn, inode-i_cdev);，如果不想看到该调 试消息，就只需要简单的将PDEBUG改为PDEBUGG即可。而当我们调试完毕形成 最终产品时，只需要简单地将第1行注释掉即可。上边那一段代码中的_KERNEL_是内核中定义的宏，当

7、我们编译内核(包括模块) 时，它会被定义。当然如果你不明白代码中的.和#是什么意思的话，就请认 真查阅一下gcc关于预处理部分的资料吧！如果你实在太懒不愿意去查阅的话， 那就充当VC工程师把上面的代码copy到你的代码中去吧。二、查看OOP消息OOP意为惊讶。当你的驱动有问题，内核不惊讶才怪：嘿！小子，你干吗乱来！ 好吧，就让我们来看看内核是如何惊讶的。根据 faulty.c 编译出 faulty.ko，并 insmod faulty.ko。执行 echoyang /dev/faulty，结果内核就惊讶了。内核为什么会惊讶呢？因为faulty 驱动的write函数执行了*(int *)0 =

8、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 00000000pgd = c389400000000000 *pgd=33

9、830031, *pte=00000000, *ppte=00000000Internal error: Oops: 817 #1 PREEMPTModules linked in: faulty scullCPU: 0 Not tainted (2.6.22.6 #4)PC is at faulty_write+0 x10/0 x18 faultyLR is at vfs_write+0 xc4/0 x148pc : lr : psr: a000001310sp :c3871f44ipc3871f54fpc3871f5011r10:4021765cr9 :c3870000r800000000

10、12r7 :00000004r6 :c3871f78r540016000 r4 : c38e516013r3 :c3871f78r2 :00000004r140016000 r0 : 00000000Flags: NzCv IRQs on FIQs on Mode SVC_32 Segment userControl: c000717f Table: 33894000 DAC: 00000015Process sh (pid: 745, stack limit = 0 xc3870258)Stack: (0 xc3871f44 to 0 xc3872000)1f40:c3871f74 c387

11、1f54 c0088eb8 bf00608c 00000004 c38e5180c38e51601f60: c3871f78 00000000 c3871fa4 c3871f78 c0088ffc c0088e04 00000000 000000001f80: 00000000 00000004 40016000 40215730 00000004 c002c0e4 00000000 c3871fa81fa0: c002bf40 c0088fc0 00000004 40016000 00000001 40016000 00000004 000000001fc0: 00000004 400160

12、00 40215730 00000004 00000001 00000000 4021765c 000000001fe0: 00000000 bea60964 0000266c 401adb40 60000010 00000001 0000000000000000Backtrace: (faulty_write+0 x0/0 x18 faulty) from (vfs_write+0 xc4/0 x148) (vfs_write+0 x0/0 x148) from (sys_write+0 x4c/0 x74)r7:00000000 r6:c3871f78 r5:c38e5160 r4:c38

13、e5180 (sys_write+0 x0/0 x74) from (ret_fast_syscall+0 x0/0 x2c)r8:c002c0e4 r7:00000004 r6:40215730 r5:40016000 r4:00000004Code: e1a0c00d e92dd800 e24cb004 e3a00000 (e5800000)1行惊讶的原因，也就是报告出错的原因2-4行是OOP信息序号；5行是出错时内核已加载模块；6行是发生错误的CPU序号；7-15行是发生错误的位置，以及当时CPU各个寄存器的值，这最有利于 我们找出问题所在地；16行是当前进程的名字及进程ID17-23行

14、是出错时，栈内的内容24-29行是栈回溯信息，可看出直到出错时的函数递进调用关系(确保 CONFIG_FRAME_POINTER 被定义)30行是出错指令及其附近指令的机器码，出错指令本身在小括号中反汇编 faulty.ko ( arm-linux-objdump -D faulty.ko faulty.dis ； cat faulty.dis)可以看到如下的语句如下：0000007c :7c:e1a0c00dmovip,sp80:e92dd800stmdbsp!,fp, ip, lr, pc84:e24cb004subfp,ip, #4; 0 x488:e3a00000movr0,#0 ;

15、0 x08c:e5800000strr0,r090:e89da800ldmiasp,fp, sp, pc定位出错位置以及获取相关信息的过程:9 pc : lr : psr: a0000013 (faulty_write+0 x0/0 x18 faulty) from (vfs_write+0 xc4/0 x148) (vfs_write+0 x0/0 x148) from (sys_write+0 x4c/0 x74)出错代码是faulty_write函数中的第5条指令(0 xbf00608c-0 xbf00607c)/4+1=5 ),该函数的首地址是 0 xbf00607c,该函数 总共6条

16、指令(0 x18)，该函数是被0 xc0088eb8的前一条指令调用的(即：函 数返回地址是0 xc0088eb8。这一点可以从出错时lr的值正好等于0 xc0088eb8 得到印证)。调用该函数的指令是vfs_write的第49条(0 xc4/4=49)指令。达到出错处的函数调用流程是：write(用户空间的系统调用)-sys_write-vfs_write-faulty_writeOOP消息不仅让我定位了出错的地方，更让我惊喜的是，它让我知道了一些秘密:1、gcc中fp到底有何用处？ 2、为什么gcc编译任何函数的时候，总是要把3 条看上去傻傻的指令放在整个函数的最开始？ 3、内核和gdb

17、是如何知道函数调 用栈顺序，并使用函数的名字而不是地址？ 4、我如何才能知道各个函数入栈的 内容？哈哈，我渐渐喜欢上了让内核惊讶，那就再看一次内核惊讶吧。执行cat /dev/faulty，内核又再一次惊讶！Unable to handle kernel NULL pointer dereference at virtual address 0000000bpgd = c3a880000000000b *pgd=33a79031, *pte=00000000, *ppte=00000000Internal error: Oops: 13 #2 PREEMPTModules linked in:

18、 faultyCPU: 0 Not tainted (2.6.22.6 #4)PC is at vfs_read+0 xe0/0 x140LR is at 0 xffffffffpc : lr : psr: 2000001310 sp :c38d9f54ip:0000001cfp :ffffffff11 r10:00000001r9: c38d8000r8 :0000000012 r7 :00000004r6: ffffffffr5 :ffffffff r4 : ffffffff13 r3 :ffffffffr2: 00000000r1 :c38d9f38 r0 : 0000000414 Fl

19、ags:nzCvIRQson FIQs onModeSVC_32 Segment userControl: c000717f Table: 33a88000 DAC: 00000015Process cat (pid: 767, stack limit = 0 xc38d8258)Stack: (0 xc38d9f54 to 0 xc38da000)9f40:00002000c3c105a0 c3c105809f60: c38d9f78 00000000 c38d9fa4 c38d9f78 c0088f88 c0088bb4 00000000 000000009f80: 00000000 00

20、002000 bef07c80 00000003 00000003 c002c0e4 00000000 c38d9fa89fa0: c002bf40 c0088f4c 00002000 bef07c80 00000003 bef07c80 00002000 000000009fc0: 00002000 bef07c80 00000003 00000000 00000000 00000001 00000001 000000039fe0: 00000000 bef07c6c 0000266c 401adab0 60000010 00000003 00000000 00000000Backtrace

21、: invalid frame pointer 0 xffffffffCode: ebffff86 e3500000 e1a07000 da000015 （e594500c）Segmentation fault不过这次惊讶却令人大为不解。OOP竟然说出错的地方在vfs_read （要知道它可 是大拿们千锤百炼的内核代码），这怎么可能？哈哈，万能的内核也不能追踪函 数调用栈了，这是为什么？其实问题出在faulty_read的43行，它导致入栈的 r4、r5、r6、fp 全部变为了 0 xffffffff，ip、lr 的值未变，这样一来 faulty_read 函数能够成功返回到它的调用者 vfs

22、_read。但是可怜的vfs_read （忠实的 APTCS规则遵守者）并不知道它的r4、r5、r6已经被万恶的faulty_read改变， 这样下去vfs_read命运就可想而知了一一必死无疑！虽然内核很有能力，但缺 少了正确的fp的帮助，它也无法追踪函数调用栈。36 ssize)_t faulty_read(struct file *filp, char_user *buf,37size_t count, loff_t *pos)38 (39int ret;40char stack_buf4;4142/* Lets trya buffer overflow */43memset(stack

23、_buf, 0 xff,20);44if (count 4)45count = 4; /* copy 4 bytesto the user */46ret = copy_to_user(buf,stack_buf,count);47if (!ret)48return count;49return ret;50 00000000:0:e1a0c00dmovip,sp4:e92dd870stmdb sp!,r4, r5,r6, fp, ip, lr, pc8:e24cb004subfp,ip, #4;0 x4c:e24dd004subsp,sp, #4;0 x4,这里为 stack_buf在栈上分

24、配1个字的空间，局部变量ret使用寄存器存储，因此就不在栈上分配空间了10:e24b501csubr5,fp, #28;0 x1c14:e1a04001movr4,r118:e1a06002movr6,r21c:e3a010ffmovr1,#255;0 xff20:e3a02014movr2,#20 ; 0 x1424:e1a00005movr0,r528:ebfffffememsetbl28 这里在调用78:e89da878Idmia sp, r3, r4, r5, r6, fp, sp, pc这次OOP，让我深刻地认识到：内核能力超强，但它不是，也不可能是万能的。所以即使你能力再强，也 要

25、和你的team member搞好关系，否则在关键时候你会倒霉的；出错的是faulty_read，vfs_read却做了替罪羊。所以人不要被表面现象 所迷惑，要深入看本质；内核本来超级健壮，可是你写的驱动是内核的组成部分，由于它出错，结 果整体崩盘。所以当你加入一个团队的时候一定要告诫自己，虽然你的角 色也许并不重要，但你的疏忽大意将足以令整个非常牛X的团队崩盘。反 过来说，当你是team leader的时候，在选团队成员的时候一定要慎重、 慎重、再慎重，即使他只是一个小角色。千万别惹堆栈，它一旦出问题，定位错误将会是一件非常困难的事情。所 以，千万别惹你的领导，否则你将死得很难看。三、利用st

26、race有时小问题可以通过监视程序监控用户应用程序的行为来追踪，同时监视程序也 有助于建立对驱动正确工作的信心。例如，在看了它的读实现如何响应不同数量 数据的读请求之后，我们能够对scull正在正确运行感到有信心。有几个方法来监视用户空间程序运行。你可以运行一个调试器来单步过它的函 数，增加打印语句，或者在strace下运行程序。这里，我们将讨论最后一个技 术，因为当真正目的是检查内核代码时，它是最有用的。strace命令是一个有力工具，它能显示所有的用户空间程序发出的系统调用 它不仅显示调用，还以符号形式显示调用的参数和返回值。当一个系统调用失败, 错误的符号值(例如，ENOMEM)和对应的

27、字串(Out of memory)都显示。strace有 很多命令行选项，其中最有用的是-t来显示每个调用执行的时间，-T来显示 调用中花费的时间，-e来限制被跟踪调用的类型(例如strace-eread,write ls表示只监控read和write调用)，以及-o来重定向输出到 一个文件。缺省情况下，strace打印调用信息到stderr。strace从内核自身获取信息。这意味着可以跟踪一个程序，不管它是否带有调 试支持编译(对gcc是-g选项)以及不管它是否被strip过。此外，你也可以 追踪一个正在运行中的进程，这类似于调试器连接到一个运行中的进程并控制 它。跟踪信息常用来支持发给应用

28、程序开发者的故障报告，但是对内核程序员也是很 有价值的。我们已经看到驱动代码运行如何响应系统调用，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) = 0getdents64(3, /* 141 e

29、ntries */, 4096) = 4088.getdents64(3, /* 0 entries */, 4096) = 0close(3) = 0.fstat64(1, (st_mode=S_IFCHR|0664, st_rdev=makedev(254, 0), .) = 0 write(1, MAKEDEVnadmmidi0nadmmidi1nadmmid.， 4096) = 4000 write(1, bnptywcnptywdnptywenptywfnptyx0n.， 96) = 96 write(1, bnptyxcnptyxdnptyxenptyxfnptyy0n.， 409

30、6) = 3904 write(1, s17nvcs18nvcs19nvcs2nvcs20nvcs21.， 192) = 192 write(1, nvcs47nvcs48nvcs49nvcs5nvcs50nvc.， 673) = 673 close(1) = 0 exit_group(0) = ?从第一个write调用看，明显地，在ls结束查看目标目录后，它试图写4KB。 但奇怪的是，只有4000字节被成功写入，并且操作被重复。但当我们查看 scull中的写实现，发现它一次最多只允许写一个quantum (共4000字节)， 可见驱动本来就是期望部分写。几步之后，所有东西清空，程序成功退出。

31、正是 通过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, MAKEDEVnadmmidi0nadmmidi1nadmmid.， 16384) = 4000 read(3, bnptywcnptywdnptywenptywfnptyx0n.， 16384) = 4000 read(3

32、, s17nvcs18nvcs19nvcs2nvcs20nvcs21.， 16384) = 865 read(3, ，16384) = 0fstat64(1, (st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), .) = 0 write(1, 8865 /dev/scull0n, 17) = 17 close(3) = 0 exit_group(0) = ?如同期望的，read 一次只能获取4000字节，但是数据总量等同于前个例子写 入的。这个例子，意外的收获是：可以肯定，wc为快速读进行了优化，它因此 绕过了标准库(没有使用fscanf)，而是直接

33、一个系统调用以读取更多数据。 这一点，可从跟踪到的读的行里看到wc 一次试图读取16 KB的数据而确认。四、利用内核内置的hacking选项内核开发者在make menuconfig的Kernel hacking提供了一些内核调试选项。这些选项有助于我们调试驱动程序，因为当我们启用某些调试选项的时候，操作 系统会在发现驱动运行有问题时给出一些错误提示信息，而这些信息非常有助于 驱动开发者找出驱动中的问题所在。下面就举几个简单例子。先启用如下选项：General setup - Configure standard kernel features (for small systems) - Lo

34、ad all symbols for debugging/ksymoops (NEW)Kernel hacking - Kernel debuggingDevice Drivers - Generic Driver Options - Driver Core verbose debug messages1、Kernel debugging - Spinlock and rw-lock debugging: basic checks (NEW) 可以检查到未初始化的自旋锁2、Kernel debugging - Mutex debugging: basic checks (NEW)可以检查到 未

35、初始化的信号量717/init_MUTEX(&scull_devicesi.sem);例如，如果我们忘记了初始化scull驱动中的信号量(将main.c的第717行注 释掉)，则在open设备scull时只会产生OOP，而没有其它信息提示我们有信 号量未初始化，因此此时我们很难定位问题。相反，如果启用了上述选项，操作 系统则会产生相关提示信息，使我们知道有未初始化的信号量或者自旋锁。从而， 我们就可以去驱动代码中初始化信号量和自旋锁的地方修正程序。这个测试，我们的意外收获是：信号量的实现，其底层仍然是自旋锁。这与我们 之前的大胆推测一致。process 751 enter scull_open

36、BUG: spinlock bad magic on CPU#0, sh/751 lock: c38ac1e4, .magic: 00000000, .owner: /-1, .owner_cpu: 0 (dump_stack+0 x0/0 x14) from (spin_bug+0 x90/0 xa4) (spin_bug+0 x0/0 xa4) from (_raw_spin_lock+0 x28/0 x160) r5:40000013 r4:c38ac1e4 (_raw_spin_lock+0 x0/0 x160) from (_spin_lock_irqsave+0 x2c/0 x34

37、) (_spin_lock_irqsave+0 x0/0 x34) from (add_wait_queue_exclusive+0 x24/0 x50) r5:c38ac1e4 r4:c38a1e1c (add_wait_queue_exclusive+0 x0/0 x50) from (down_interruptible+0 x5c/0 x16c) r5:c38a0000 r4:c38ac1dc (_down_interruptible+0 x0/0 x16c) from (down_interruptible_failed+0 xc/0 x20) (scull_open+0 x0/0

38、xd8 scull) from (chrdev_open+0 x1b4/0 x1d8) r6:c3ef0300 r5:c38ac1fc r4:bf0045a03、Kernel debugging - Spinlock debugging: sleep-inside-spinlock checking (NEW)可以检查出驱动在获取自旋锁后又睡眠以及死锁等状况 345 ssleep(5);87 #define usespin例如，如果第1个进程在获得自旋锁的情况下睡眠(去掉main.c第345行的注 释，去掉scull.h第87行的注释)，当第2个进程试图获得自旋锁时将死锁系 统。但如果启用了上

39、面的选项，则在死锁前操作系统可以给出提示信息。process 763 enter read semphore get, and begin sleep 5 second in process 763 BUG: scheduling while atomic: cat/0 x00000001/763 (dump_stack+0 x0/0 x14) from (schedule+0 x64/0 x778) (schedule+0 x0/0 x778) from (schedule_timeout+0 x8c/0 xbc)process 764 enter readBUG: spinlock cpu

40、 recursion on CPU#0, cat/764 lock: c3ae7014, .magic: dead4ead, .owner: cat/763, .owner_cpu: 0 (dump_stack+0 x0/0 x14) from (spin_bug+0 x90/0 xa4) (spin_bug+0 x0/0 xa4) from (_raw_spin_lock+0 x5c/0 x160) r5:beed2c70 r4:c3ae7014 (_raw_spin_lock+0 x0/0 x160) from (_spin_lock+0 x20/0 x24) (_spin_lock+0

41、x0/0 x24) from (scull_read+0 x64/0 x210 scull) r4:c3949520 (scull_read+0 x0/0 x210 scull) from (vfs_read+0 xc0/0 x140)BUG: spinlock lockup on CPU#0, cat/764, c3ae7014 (dump_stack+0 x0/0 x14) from (_raw_spin_lock+0 x124/0 x160) (_raw_spin_lock+0 x0/0 x160) from (_spin_lock+0 x20/0 x24) (_spin_lock+0

42、x0/0 x24) from (scull_read+0 x64/0 x210 scull) r4:c3949520 (scull_read+0 x0/0 x210 scull) from (vfs_read+0 xc0/0 x140)4、Magic SysRq key可以在已经死锁的情况下，打印一些有助于定位问题的信 息魔键sysrq在大部分体系上都可用，它是用PC键盘上alt和sysrq键组合来 发出的，或者在别的平台上使用其他特殊键(详见documentation/sysrq.txt), 在串口控制台上也可用。一个第三键，与这2个一起按下，进行许多有用的动 作中的一个：. r关闭键盘原始

43、模式；用在一个崩溃的应用程序(例如X服务器)可能 将你的键盘搞成一个奇怪的状态.k调用安全注意键”(SAK)功能.SAK杀掉在当前控制台的所有运行的 进程，给你一个干净的终端.s进行一个全部磁盘的紧急同步.u umount.试图重新加载所有磁盘在只读模式.这个操作，常常在s之 后马上调用，可以节省大量的文件系统检查时间，在系统处于严重麻烦 时.b boot.立刻重启系统.确认先同步和重新加载磁盘.p打印处理器消息.t打印当前任务列表.m打印内存信息.例如，在系统死锁的情况下，期望能知道寄存器的值，则可以使用该魔法键。SysRq : Show RegsPid: 764, comm:catCPU:

44、 0 Not tainted (2.6.22.6 #6)PC is at _raw_spin_lock+0 xbc/0 x160LR is at _raw_spin_lock+0 xcc/0 x160pc :lr : psr: 60000013sp :c3b11ecc ip: c3b11e08 fp : c3b11efcr10:c3b10000 r9: 00000000 r8 : 055b131fr7 :c3ae7014 r6:00000000 r5 : 05f1e000 r4 : 00000000r3 :00000000 r2:c3b10000 r1 : 00000001 r0 : 0000

45、0001Flags:nZCv IRQson FIQs on Mode SVC_32 Segment userControl: c000717f Table: 33b48000 DAC: 00000015 (show_regs+0 x0/0 x4c) from (sysrq_handle_showregs+0 x20/0 x28)r4:c0310c34 (sysrq_handle_showregs+0 x0/0 x28) from (_handle_sysrq+0 xa0/0 x148) (_handle_sysrq+0 x0/0 x148) from (handle_sysrq+0 x30/0 x34) (handle_sysrq+0 x0/0 x34) from (s3c24xx_serial_rx_chars+0 x1b0/0 x2d4)r5:00000000 r4:c03111e4 (s3c24xx_serial_rx_chars+0 x0/0 x2d4) from (handle_IRQ_event+0 x44/0 x80) (handle_IRQ_event+0 x0/0 x80) from (handle_level_irq+0