如何更好的调试驱动--内核消息打印

在各种调试方法中,最原始也是最常用的方法就是把内核信息打印在控制台上,最为我们熟知的printk就是打印的接口,他也是所有内核信息打印的基础。由于这个函数的使用频率是如此之高,所以围绕它也需要了解一些基本的知识来帮助我们更好的得到想要的调试信息。

环形缓冲

首先需要知道的是,printk只是负责将信息输入到内核信息的缓冲区中。这个缓冲区是一个环形缓冲区,也就是说,如果我们打印的信息过多,信息来不及打印,之前的信息就会被后来的覆盖掉。此外也不可一次打印太多数据,以免超出环形缓冲区总长。

消息级别

printk共定义了0-7共8个消息级别,级别越低数值越大,消息也约不重要,0是紧急事件,7是调试事件,具体每个等级代表的含义网上可以方便的查到这里就不说了。
通过读取/proc/sys/kernel/printk我们可以得到以下信息:

root@orangepipcplus:~# cat /proc/sys/kernel/printk
3   4   1   3

以上四个数值分别代表:
1. 控制台日志级别
2. 默认消息日志级别(printk不带打印级别的情况下默认输出的级别)
3. 控制台日志可被设置的最低级别
4. 默认控制台日志级别
我们可以通过向/proc/sys/kernel/printk写入数值来调整printk输出到控制台的等级。需要注意的是,这并不会调整输入到缓冲区内的日志,只是调整显示到控制台上的日志。

查看缓冲区

常见的方法有两种,使用dmesg命令查看缓冲区内容,注意使用dmesg -c的话会同时清空缓冲区。如果没有该命令还可以通过

cat /proc/kmsg

来显示内核信息,需要注意的该文件是一个无休止的文件,所以该进程只能通过kill来终止。

封装后的printk

在实际开发过程中,我们为了分辨不同模块打印出的不同信息,往往需要打印信息具有不同的格式,Linux内核已经为我们提供了一些封装好的API。

pr_xxx()

pr_xxx()包含了各种等级的日志打印,从pr_emerg到pr_info,我们可以用过在文件开头使用一个pr_fmt()来定义接下来pr_xxx()的打印格式。

dev_xxx()

使用dev_err()和dev_info()打印信息的时候,设备名称会被自动加在打印消息的开头位置。

pr_debug()和dev_dbg()

但是需要注意的是提供给debug使用的pr_debug()以及dev_dbg(),和之前提到的其他接口有所不同,来看一下这两个函数的定义:

/* If you are writing a driver, please use dev_dbg instead */
#if defined(CONFIG_DYNAMIC_DEBUG)
/* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
#define pr_debug(fmt, ...) \
    dynamic_pr_debug(fmt, ##__VA_ARGS__)
#elif defined(DEBUG)
#define pr_debug(fmt, ...) \
    printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
#define pr_debug(fmt, ...) \
    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#endif
#if defined(CONFIG_DYNAMIC_DEBUG)
#define dev_dbg(dev, format, ...)           \
do {                             \
    dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
} while (0)
#elif defined(DEBUG)
#define dev_dbg(dev, format, arg...)       \
    dev_printk(KERN_DEBUG, dev, format, ##arg)
#else
#define dev_dbg(dev, format, arg...)               \
({                              \
    if (0)                          \
        dev_printk(KERN_DEBUG, dev, format, ##arg); \
})
#endif

从以上代码可以看出来我们对该接口有两种不同的使用方法,先来说最简单的,以pr_debug为例。
假如没有定义CONFIG_DYNAMIC_DEBUG,如果我们需要打印pr_debug()的信息,就需要在该模块里定义DEBUG,这样pr_debug()就可以正确输出相应等级的日志,如果没有定义DEBUG,那么就不会输出任何内容。那么这个接口就可以当做开发过程中调试用了,通过更改DEBUG的定义与否,来控制debug日志是否输出。缺点也十分明显,需要我们更改控制台的消息级别到7,这样显然会造成大量的日志输出,降低系统的运行效率,也不利于日志的分析。
那么另外一种方法就是通过打开CONFIG_DYNAMIC_DEBUG,启用内核的动态调试功能,注意前提是需要打开内核的debugfs(debugfs也是我们在编写驱动时候的一大调试利器,以后会有文章作为补充)。通过向debugfs中的控制文件中写入信息来控制改接口的行为。
比如我们想打开svcsock.c第1603行的日志打印,我们写入如下信息:

nullarbor:~ # echo 'file svcsock.c line 1603 +p' >
                              <debugfs>/dynamic_debug/control

此外我们还可以读取当前的动态打印状态:

nullarbor:~ # cat <debugfs>/dynamic_debug/control
# filename:lineno [module]function flags format
/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:323 [svcxprt_rdma]svc_rdma_cleanup =_ "SVCRDMA Module Removed, deregister RPC RDMA transport\012"
/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:341 [svcxprt_rdma]svc_rdma_init =_ "\011max_inline       : %d\012"
/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:340 [svcxprt_rdma]svc_rdma_init =_ "\011sq_depth         : %d\012"
/usr/src/packages/BUILD/sgi-enhancednfs-1.4/default/net/sunrpc/svc_rdma.c:338 [svcxprt_rdma]svc_rdma_init =_ "\011max_requests     : %d\012"
...

这里只简单说明一下dynamic debug的用法,具体的语法请参照kernel doc,在文末可以找到链接。

总结时间

首先一定不要滥用日志打印,日志的输出是有代价的。在实际使用的时候我们需要控制日志的优先级,在调试或者发布的时候来打开不同的flag来控制日志的输出等级。所以说在任何时候都不要直接使用print类函数,通过对这些函数的重新封装,我们可以获得更好的灵活性。

参考资料:
https://www.kernel.org/doc/html/v4.11/admin-guide/dynamic-debug-howto.html

点赞

发表评论

电子邮件地址不会被公开。 必填项已用*标注