内核调试信息printk/pr_debug()/dev_dbg()

前言

一 printk的打印等级

        很多内核开发者最喜欢的调试工具之一是printk。printk是内核提供的格式化打印函数，它和C库所提供的printf()函数类似。printk()函数和printf()函数的一个重要区别是前者提供打印等级，内核根据这个等级来判断是否在终端或者串口中打印输出。从我多年的工程实践经验来看，printk是最简单有效的调试方法。

        位于Kern_levels.h (include\linux) 文件。注意KERN_DEBUG展开后值是"\001""1""，中间的空格省略掉也没关系吗，没关系。

#define KERN_SOH	"\001"		/* ASCII Start Of Header */
#define KERN_SOH_ASCII	'\001'

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

#define KERN_DEFAULT	KERN_SOH "d"	/* the default kernel loglevel */

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

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

二 printk使用

和printf一样，printk也是可以格式化打印的，打印格式如下：这个格式我基本是记不住，要是警告都我强制转换(#^.^#)。

 可以直接使用printk("hello world");

也可以使用等级打印printk(KERN_DEBUG"hello world");

也可以将printk包装为宏定义，这是我最喜欢干的事情

#define DEBUG_CSS(format,...)\
		printk("\001""1""info:%s:%s:%d: "format"\n",\
		__FILE__,__func__,__LINE__,\
		##__VA_ARGS__)

#define DEBUG_CSS_ERR(format,...)\
		printk("\001""1""error:%s:%s:%d: "format"\n",\
		__FILE__,__func__,__LINE__,\
		##__VA_ARGS__)

三 /proc/sys/kernel/printk*文件

        /proc/sys/kernel/printk

        /proc目录中有很多有用的文件，这些文件真实的表达了内核的动态信息、运行状态、进程状态、中断状态、定时器状态、IO状态、misc驱动信息，网络状态、各种内存的统计信息、系统的启动时长等等。
        读取printk的打印等级。     

root@ATK-IMX6U:/proc/sys/kernel# cat printk
7       4       1       7
root@ATK-IMX6U:/proc/sys/kernel#

   这四个数字的含义分别是：

7：表示控制台打印等级、

        printk时，传递给它的KERN_XXX，KERN_XXX如果大于7，在控制台就看不到调试信息。使用dmesg就又可以看到了，

4：默认消息打印等级

1：最低打印等级:

7：默认控制台打印等级。

        调整打印等级为3，

echo 3 > /proc/sys/kernel/printk

root@ATK-IMX6U:/proc/sys/kernel# cat printk
3       4       1       7
root@ATK-IMX6U:/proc/sys/kernel#

        测试发现，这个值只能往小了改，不能往大了改。例如现在是3，改成7，就改不成，难道这个和内核版本有关系？那想改回原来的值怎么办，莫慌，重启以后，就会恢复默认值了。

root@ATK-IMX6U:/proc/sys/kernel# cat printk
7       4       1       7
root@ATK-IMX6U:/proc/sys/kernel# echo 6 > printk
root@ATK-IMX6U:/proc/sys/kernel# cat printk
6       4       1       7
root@ATK-IMX6U:/proc/sys/kernel# echo 7 printk
7 printk
root@ATK-IMX6U:/proc/sys/kernel# cat printk
6       4       1       7
root@ATK-IMX6U:/proc/sys/kernel#

/proc/sys/kernel/printk_delay

这个是干什么的呢？

dmesg命令

如果调试信息看不到，就使用dmesg命令。

动态输出pr_debug()/dev_dbg()

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

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

我的内核默认没有开启这个功能，DEBUG_FS=n

 DEBUG_FS位置：

 配置如下所示，然后重新编译内核：

这个Enable dynamic printk() support如何依赖项没有配置，它是隐藏技能，看不到的。

 

 使用新内核后，/sys/kernel目录多了debug文件夹：

root@ATK-IMX6U:/sys/kernel/debug# ls
asoc  bluetooth  ci_hdrc.1  dma_buf  dynamic_debug  fault_around_bytes  hid        iio       mmc0  pinctrl  pwm     regulator   suspend_stats  ubifs  wakeup_sources
bdi   ci_hdrc.0  clk        dri      extfrag        gpio                ieee80211  memblock  mmc1  pm_qos   regmap  sleep_time  ubi            usb
root@ATK-IMX6U:/sys/kernel/debug#

dynamic_debug文件夹下有个control文件，该中存有大量的调试信息：

看看前10行和后10行

root@ATK-IMX6U:/sys/kernel/debug/dynamic_debug# head -n 10 control
# filename:lineno [module]function flags format
init/main.c:712 [main]initcall_blacklist =p "blacklisting initcall %s\012"
init/main.c:736 [main]initcall_blacklisted =p "initcall %s blacklisted\012"
init/initramfs.c:483 [initramfs]unpack_to_rootfs =_ "Detected %s compressed data\012"
arch/arm/vfp/vfpmodule.c:304 [vfp]vfp_emulate_instruction =_ "VFP: emulate: INST=0x%08x SCR=0x%08x\012"
arch/arm/vfp/vfpmodule.c:260 [vfp]vfp_raise_exceptions =_ "VFP: raising exceptions %08x\012"
arch/arm/vfp/vfpmodule.c:456 [vfp]vfp_pm_suspend =_ "%s: saving vfp state\012"
arch/arm/vfp/vfpmodule.c:340 [vfp]VFP_bounce =_ "VFP: bounce: trigger %08x fpexc %08x\012"
arch/arm/vfp/vfpsingle.c:51 [vfp]vfp_single_dump =_ "VFP: %s: sign=%d exponent=%d significand=%08x\012"
arch/arm/vfp/vfpsingle.c:849 [vfp]vfp_single_multiply =_ "VFP: swapping M <-> N\012"
root@ATK-IMX6U:/sys/kernel/debug/dynamic_debug#

root@ATK-IMX6U:/sys/kernel/debug/dynamic_debug# tail -n 10 control
net/bluetooth/hidp/core.c:149 [hidp]hidp_input_event =_ "session %p type %d code %d value %d\012"
net/bluetooth/hidp/core.c:1402 [hidp]hidp_get_connlist =_ "\012"
net/bluetooth/hidp/sock.c:233 [hidp]hidp_sock_create =_ "sock %p\012"
net/bluetooth/hidp/sock.c:60 [hidp]hidp_sock_ioctl =_ "cmd %x arg %lx\012"
net/bluetooth/hidp/sock.c:36 [hidp]hidp_sock_release =_ "sock %p sk %p\012"
net/wireless/reg.c:547 [cfg80211]call_crda =_ "Exceeded CRDA call max attempts. Not calling CRDA\012"
net/wireless/reg.c:553 [cfg80211]call_crda =_ "Calling CRDA for country: %c%c\012"
net/wireless/reg.c:555 [cfg80211]call_crda =_ "Calling CRDA to update world regulatory domain\012"
net/mac80211/mlme.c:1354 [mac80211]ieee80211_handle_pwr_constr =p "%s: Limiting TX power to %d (%d - %d) dBm as advertised by %pM\012"
net/mac80211/mlme.c:1359 [mac80211]ieee80211_handle_pwr_constr =p "%s: Limiting TX power to %d dBm as advertised by %pM\012"
root@ATK-IMX6U:/sys/kernel/debug/dynamic_debug# 

那么如何打开动态输出语句呢？

直接写一个简单的模块，并在模块中添加如下两个语句

	pr_debug("css_init init ok");
	dev_dbg(css_dev->misc.this_device, "css_init init ok");

加载该模块后，显示control文件后四行的信息：看到我们动态调试信息。

root@ATK-IMX6U:~# tail -n 4 /sys/kernel/debug/dynamic_debug/control
net/mac80211/mlme.c:1359 [mac80211]ieee80211_handle_pwr_constr =p "%s: Limiting TX power to %d dBm as advertised by %pM\012"
/big/csi_driver/css_dma/csi_single.c:161 [csi_single]css_init =_ "css_init init ok"
/big/csi_driver/css_dma/csi_single.c:188 [csi_single]css_init =_ "css_init init ok"
/big/csi_driver/css_dma/csi_single.c:189 [csi_single]css_init =_ "css_init init ok"
root@ATK-IMX6U:~#

下面的内容，先抄写过来。

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

// 打开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/arm/kernel/smp.c:354 [smp]secondary_start_kernel =pflt "CPU%u: Bootedsecondary processor\012"

        在内核命令行中添加“smp.dyndbg=+plft”字符串。

#qemu-system-arm -M vexpress-a9 -m 1024M -kernel arch/arm/boot/zImage-append "rdinit=/linuxrc console=ttyAMA0 loglevel=8 smp.dyndbg=+plft" -dtbarch/arm/boot/dts/vexpress-v2p-ca9.dtb -nographic -smp 4

[…]

/ # dmesg | grep "Booted" //查询SMP模块的动态输出语句是否打开[0] secondary_start_kernel:354: CPU1: Booted secondary processor[0] secondary_start_kernel:354: CPU2: Booted secondary processor[0] secondary_start_kernel:354: CPU3: Booted secondary processor

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

[…/Makefile]

ccflags-y := -DDEBU

Gccflags-y += -DVERBOSE_DEBUG

扩展函数：

还有两个函数，在其他文章中介绍

打印内存的数据函数print_hex_dump()

打印堆栈函数dump_stack()

小结