Linux驱动调试之printk

在Linux调试中,加printk等打印可以解决大部分问题。在Linux默认代码中,常会看到封装了printk() 的更高级的宏,比如dev_info(),  dev_dbg(),  pr_info(), pr_debug()等。但是有些信息并没有输出到控制台(串口)。本文以i.MX8MP EVK, L6.1.36 Linux版本为例,列出了一些Linux利用printk常用的调试手段:

•          printk的级别定义,如何调节日志等级

•          动态调试 (dynamic debug):即在运行Linux时将指定驱动文件的dev_dbg, pr_debug等输出到控制台(串口)

•          静态调试 (debug):即在编译内核时将指定驱动文件的dev_dbg, pr_debug等输出到控制台(串口)

•          修改kernel顶层Makefile, 将所有驱动文件的dev_dbg, pr_debug等输出到控制台(串口)

•          利用initcall_debug跟踪initcall

•          其他模块的debug: 如drm debug

•          手动WARN_ON(1), BUG_ON(1)查看栈回溯

1.     预定开发板

在动手实践本应用案例前先预定开发板:(以i.MX8MP为例,i.MX93等同样适用)

2.     printk的级别定义,如何调节日志等级:

内核打印语句printk()会将内核信息输出到内核信息缓冲区中,它是一个环形缓冲区,塞入消息过多会把之前的消息冲掉。Linux内核可通过调节CONFIG_LOG_BUF_SHIFT宏来扩大缓冲区大小。

Printk()定义了8个消息级别,分别为0~7。数值越大,级别越低,消息越不重要。第0级是紧急事件,第7级是调试级。

vi include/linux/kern_levels.h

#definKERN_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 */e

其中,KERN_EMERG(等级0)为紧急事件,一般是系统崩溃前的信息。KERN_ERR(等级1)用于报告错误状态,设备驱动程序常采用此等级的打印报告自身硬件问题。KERN_INFO(等级6)是内核提示性信息,驱动程序在启动的时候常用此等级的打印报告硬件信息。KERN_DEBUG(等级7)是调试信息。

用户可以直接用不带flag的printk打印,默认的优先级是4,即直接printk(“XXX“);。也可以选择添加打印等级,比如用printk(KERN_DEBUG “XXX“);或者printk(KERN_INFO “XXX“)。

在打印时,可以使用__func__输出printk所在的函数名,使用__LINE__输出所在代码的行号,使用__FILE__输出源代码的文件名。

例如,按照“编译内核镜像并在云实验室开发板运行.docx“编译内核源码,其中对源码添加如下打印:

git diff

diff --git a/drivers/gpu/drm/bridge/sec-dsim.c b/drivers/gpu/drm/bridge/sec-dsim.c

index fc9ca98f6ef7..ea5fbec61209 100644

--- a/drivers/gpu/drm/bridge/sec-dsim.c

+++ b/drivers/gpu/drm/bridge/sec-dsim.c

@@ -1146,6 +1146,9 @@ struct dsim_pll_pms *sec_mipi_dsim_calc_pmsk(struct sec_mipi_dsim *dsim)

       struct sec_mipi_dsim_range pr_new = *prange;

       struct sec_mipi_dsim_range sr_new = *srange;

+       printk(KERN_INFO "sec_mipi_dsim_calc_pmsk start, function name is %s,\

+       line is %d, file name is %s\n ", __func__, __LINE__, __FILE__ );

+

       pll_pms = devm_kzalloc(dev, sizeof(*pll_pms), GFP_KERNEL);

       if (!pll_pms) {

               dev_err(dev, "Unable to allocate 'pll_pms'\n");

编好的kernel Image通过以下方式上传至8MPLUSLPD4-PEVK-3开发板的TFTP目录。

再点击PowerReset EVK按钮,重启开发板。之后可以看到以下打印出现。可以作为调试的一种手段。

通过以下命令可查看printk()的输出等级:

cat /proc/sys/kernel/printk

该文件有4个值,依次为:

(1)    控制台(一般是串口)的日志级别, console_loglevel:当前的打印级别,优先级高于该值的将被打印至控制台。

(2)    默认的消息级别, default_message_loglevel:打印没有优先级前缀的消息,即直接printk(“XXX“);的信息。由内核的宏CONFIG_MESSAGE_LOGLEVEL_DEFAULT控制默认值,默认为4,取值1~7。

(3)    最低的控制台日志级别, minimum_console_loglevel:控制台日志级别可设置的最小值(一般为1)。

(4)    默认的控制台日志级别, default_console_loglevel:控制台日志级别的默认值。由内核的宏CONFIG_CONSOLE_LOGLEVEL_DEFAULT控制默认值,默认为7,取值1~15。

通过以下命令可修改控制台的日志级别,以下命令修改为8:

echo 8 4 1 7> /proc/sys/kernel/printk

或者以下命令:

dmesg -n 8

在Linux默认代码中,常会看到封装了printk的更高级的宏,比如dev_info, dev_dbg, pr_info, pr_debug等。但是有些信息并没有输出到控制台(串口)。

以i.MX8MP EVK, L6.1.36 Linux版本为例,若采用默认的Linux kernel, 在启动过程中及利用dmesg查看开机信息时,可以看到pr_debug(),dev_dbg(),和printk(KERN _DEBUG “XXX“);等信息并未没有输出到控制台(串口)。即KERN_DEBUG(等级7)的调试信息没有输出到串口。除此之外,消息级别为0~6的调试信息均可输出到串口。

有时在调试Linux kernel时,我们希望某些文件的pr_debug(),dev_dbg(),和printk(KERN DEBUG “XXX“);等信息也输出到控制台(串口)。如何操作呢?这时候我们需要借助动态调试 (dynamic debug)或者静态调试 (debug)。

3.     动态调试 (dynamic debug):

Dynamic debug(dyndbg) 功能,就是允许用户空间通过 debugfs 导出的文件节点 /sys/kernel/debug/dynamic_debug/control,动态的、在运行时控制 Linux 内核 KERN_DEBUG 类型日志的开启和关闭。

在没开启动态调试时,直到下次重新编译内核做出改变之前,内核 KERN_DEBUG 类型日志要么一直关闭,要么一直开启,无法在运行时做出调整。

在开启动态调试后,指定驱动文件的KERN_DEBUG 等级的打印信息,即利用pr_debug(), dev_dbg(), print_hex_dump_debug(), print_hex_dump_bytes(), printk(KERN_DEBUG “XXX“);的信息均可打印至控制台。

默认Linux kernel没有使能动态调试,若使能,需要在imx_v8_defconfig或者menuconfig中设置CONFIG_DYNAMIC_DEBUG=Y(默认为N) 和 CONFIG_DEBUG_FS=Y(默认为Y)。设置成功后,编译成新的kernel Image,同样方式上传至板子的TFTP目录。

3.1 若用户想要在kernel运行时查看某个驱动文件的KERN_DEBUG等级的打印信息,可以通过以下命令查看drivers/gpu/drm/bridge/sec-dsim.c的KERN_DEBUG信息,其中“pfl”是flags, p代表打印log信息,f代表打印函数名,l代表打印代码行数:

echo -n "file drivers/gpu/drm/bridge/sec-dsim.c  +pfl " >

/sys/kernel/debug/dynamic_debug/control

dmesg |grep sec

结合Linux drivers/gpu/drm/bridge/sec-dsim.c驱动的源码,可以看到dev_dbg的信息已经被打印。

3.2 若用户想要在kernel启动时查看某个驱动文件的KERN_DEBUG等级的打印信息,且线下有开发板,可以通过以下方法修改bootargs。以下代码修改drivers/gpu/drm/bridge/sec-dsim.c,需要修改dtb并外接MIPI DSI屏幕:

u-boot=> env edit mmcargs

edit: setenv bootargs ${jh_clk} ${mcore_clk} console=${console} root=${mmcroot}  "dyndbg=\"file drivers/gpu/drm/bridge/sec-dsim.c +pfl"\"

u-boot=> saveenv

Saving Environment to MMC... Writing to MMC(1)... OK

u-boot=>

启动kernel后输入dmesg, 可以看到如下log:

结合Linux drivers/gpu/drm/bridge/sec-dsim.c驱动的源码,可以看到dev_dbg的信息已经被打印。

4.    静态调试 (debug):

如果用户不需要像动态调试那样,在运行时控制 Linux 内核 KERN_DEBUG 类型日志的开启和关闭,可以采用静态调试。该调试方法需要重新编译内核才能做出改变。具体需要在想打印的驱动文件头部,加入#define DEBUG。

仍以驱动文件drivers/gpu/drm/bridge/sec-dsim.c为例,按照以下方式修改kernel并重新做出编译后。上传至云实验室开发板的TFTP目录,

diff --git a/drivers/gpu/drm/bridge/sec-dsim.c b/drivers/gpu/drm/bridge/sec-dsim.c

index fc9ca98f6ef7..a042be9c713c 100644

--- a/drivers/gpu/drm/bridge/sec-dsim.c

+++ b/drivers/gpu/drm/bridge/sec-dsim.c

@@ -14,6 +14,7 @@

 * GNU General Public License for more details.

 */

+#define DEBUG

#include <asm/unaligned.h>

#include <linux/clk.h>

#include <linux/completion.h>

即使不设置CONFIG_DYNAMIC_DEBUG=Y, 也可以将KERN_DEBUG等级的打印信息输出到控制台,达到动态调试一样的效果:

5.    修改kernel顶层Makefile, 将所有驱动文件的dev_dbg, pr_debug等输出到控制台(串口):以上动态调试和静态调试的方法,需要明确的知道要调试的驱动文件。如果是启动时出现问题(如启动时候hang死),或者要调试的文件很多,或者在调试初期无法定位问题出现在哪个文件时,我们希望把build-in的所有文件的KERN_DEBUG 类型日志均输出到控制台,这种情况下如何调试呢?

我们可以在Linux kernel顶层的Makefile中KBUILD_CFLAGS后添加-DDEBUG。它会将DEBUG宏设置为已定义状态, 其作用相当于在所有函数头都添加#define DEBUG。具体修改如下:

diff --git a/Makefile b/Makefile

index cffb83d7a0fb..1837d6f43a0e 100644

--- a/Makefile

+++ b/Makefile

@@ -570,7 +570,7 @@ KBUILD_CFLAGS   := -Wall -Wundef -Werror=strict-prototypes -Wno-trigraphs \

                  -fno-strict-aliasing -fno-common -fshort-wchar -fno-PIE \

                  -Werror=implicit-function-declaration -Werror=implicit-int \

                  -Werror=return-type -Wno-format-security \

-                  -std=gnu11

+                  -std=gnu11 -DDEBUG

KBUILD_CPPFLAGS := -D__KERNEL__

KBUILD_RUSTFLAGS := $(rust_common_flags) \

                   --target=$(objtree)/rust/target.json \

做以上修改后,编译可能需要较长时间, 尤其是”make -j$(nproc)”。可以用“make Image”命令只编译kernel Image, 不编译内核模块。

替换kernel Image后,启动到文件系统需要较长时间,大概230s。中间会出现大量无关的、重复的日志,可能会影响启动时序,甚至导致无法login。不过利用这些日志仍然能解决一些启动过程中的问题。

结合Linux drivers/gpu/drm/imx/imx8mp-hdmi-pavi.c驱动的源码,可以看到dev_dbg的信息已经被打印。

6.   利用initcall_debug跟踪initcall:

在Linux kernel启动过程中,会通过initcall机制调用初始化函数。initcall_debug是一个内核参数,可以跟踪initcall,用来定位内核初始化的问题。

若用户线下有开发板,可以用以下命令修改bootargs使能initcall_debug:

setenv mmcargs "${mmcargs}  initcall_debug loglevel=8"

saveenv

可以看到各函数的initcall信息在启动时被打印至控制台。这些信息有助于帮助我们定位内核启动和初始化时的一些问题,获得更多信息。

因为云实验室安全的限制,开发板在U-boot阶段均不能修改bootargs,且均为网络启动。用户可以按照以下步骤通过修改imx_v8_defconfig的方式,固定command line:

第一次启动板子时,在dmesg中找到kernel cmdline

console=ttymxc1,115200 root=/dev/nfs ip=dhcp

nfsroot=192.168.100.250:/opt/REAL/NFS/IMX8MPEVK-3-root,v3,tcp

修改defconfig文件使能initcall_debug:

diff --git a/arch/arm64/configs/imx_v8_defconfig b/arch/arm64/configs/imx_v8_defconfig

index 85762b37006f..16d8a67b5bd3 100644

--- a/arch/arm64/configs/imx_v8_defconfig

+++ b/arch/arm64/configs/imx_v8_defconfig

@@ -1105,3 +1105,5 @@ CONFIG_CORESIGHT_STM=m

CONFIG_CORESIGHT_CPU_DEBUG=m

CONFIG_CORESIGHT_CTI=m

CONFIG_MEMTEST=y

+CONFIG_CMDLINE_FORCE=y

+CONFIG_CMDLINE="ttymxc1,115200 root=/dev/nfs ip=dhcp

nfsroot=192.168.100.250:/opt/REAL/NFS/IMX8MPEVK-3-root,v3,tcp initcall_debug loglevel=8

同样可以看到各函数的initcall信息在启动时被打印至控制台。

7.    其他模块的debug: 如drm debug:

除了printk, dev_xxx, pr_xx系列的打印,有些模块还有自己专属的打印。比如Linux DRM子系统,其驱动中会有DRM_DEBUG,DRM_DEBUG_DRIVER,DRM_DEBUG_ATOMIC,DRM_DEBUG_KMS等打印。这些函数的定义是在include/drm/drm_print.h路径下,其本质也是调用了printk函数。

DRM也规定了几个打印机别,例如:

* drm.debug=0x1 will enable CORE messages

* drm.debug=0x2 will enable DRIVER messages

* drm.debug=0x3 will enable CORE and DRIVER messages

* ...

* drm.debug=0x3f will enable all messages

在Linux启动后,通过

echo 0x1ff > /sys/module/drm/parameters/debug

或者在kernel编译时,修改defconfig文件使能drm debug,可将所以DRM相关的打印输出到控制台,便于调试显示相关的问题:

diff --git a/arch/arm64/configs/imx_v8_defconfig b/arch/arm64/configs/imx_v8_defconfig

index 85762b37006f..16d8a67b5bd3 100644

--- a/arch/arm64/configs/imx_v8_defconfig

+++ b/arch/arm64/configs/imx_v8_defconfig

@@ -1105,3 +1105,5 @@ CONFIG_CORESIGHT_STM=m

CONFIG_CORESIGHT_CPU_DEBUG=m

CONFIG_CORESIGHT_CTI=m

CONFIG_MEMTEST=y

+CONFIG_CMDLINE_FORCE=y

+CONFIG_CMDLINE="ttymxc1,115200 root=/dev/nfs ip=dhcp

nfsroot=192.168.100.250:/opt/REAL/NFS/IMX8MPEVK-3-root,v3,tcp drm.debug=0x1FF loglevel=8"

启动后可见DRM debug相关的信息。

8.     手动WARN_ON(1), BUG_ON(1)查看栈回溯:

内核中有BUG_ON()和WARN_ON()的语句,在括号中的条件成立时,便会抛出oops信息。我们可以将其作为一个调试技巧。如果我们想知道内核的某个函数是怎样被调用的,可以在该函数中加一个WARN_ON(1), 观察其调用关系:

diff --git a/drivers/gpu/drm/bridge/sec-dsim.c b/drivers/gpu/drm/bridge/sec-dsim.c

index fc9ca98f6ef7..42f647c14e2e 100644

--- a/drivers/gpu/drm/bridge/sec-dsim.c

+++ b/drivers/gpu/drm/bridge/sec-dsim.c

@@ -1146,6 +1146,7 @@ struct dsim_pll_pms *sec_mipi_dsim_calc_pmsk(struct sec_mipi_dsim *dsim)

       struct sec_mipi_dsim_range pr_new = *prange;

       struct sec_mipi_dsim_range sr_new = *srange;

+       WARN_ON(1);

       pll_pms = devm_kzalloc(dev, sizeof(*pll_pms), GFP_KERNEL);

       if (!pll_pms) {

               dev_err(dev, "Unable to allocate 'pll_pms'\n");