printk

前言

内核调试是做底层开发必须会的手段。有n多中调试方式，不过呢，我最终还是觉得直接printk打印是最省事的，不依赖安装其他工具，不受限与中断上下文、进程上下文、持锁、smp等（当然，在某些情景下不会省时）。下面就总结下printk的一些技巧，毕竟也没那么简单^_

printk使用

printk的使用和应用函数printf类似，不过也额外添加了一些格式支持，比如%pf（只打印函数指针的函数名，不打印偏移地址）、%pF（可打印函数指针的函数名和偏移地址）、%pM（打印冒号分隔的MAC地址）、%pm（打印MAC地址的16进制无分隔）、%I4（打印无前导0的IPv4地址，%i4打印冒号分隔的IPv4地址）、%I6（打印无前导0的IPv6地址，%i6打印冒号分隔的IPv6地址）等等。它的内部实现是基于环形缓冲，因此，即使在控制台或者串口还未初始化好的时候，我们也能用printk，它会暂时将打印信息放到环形缓冲里，等到控制台或者串口初始化好的时候，再将缓冲的所有数据打印出来。当然这里也不是打印所有的数据，这就涉及到printk的打印等级和默认等级问题，暂时列为问题1吧。同时，如果kernel在控制台或者串口还未初始化好的时候，就oops了，而我们又想看看缓冲区里的信息，怎么办？暂时列为问题2吧。最后，有时候会发现最开始的一部分打印没了，这设计缓冲区size问题，暂时列为问题3吧。

问题1：printk等级

printk的时候，需要添加一个宏来表示当前打印的等级，不加的话，会采用默认等级（默认等级可以通过CONFIG_DEFAULT_MESSAGE_LOGLEVEL来配置：make menuconfig-> Kernel Hacking -> Default message log level，默认一般为4）。只有等级高于当前等级（等级值越小，越高），启动的时候才会被打印出来。当然，启动后可以dmesg查看所有等级（也可以用dmesg -n x(x 为0-7的等级号)，如dmesg -n 3将显示等级0 1 2 3的消息）。总共有以下等级：

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

printk举例：

printk(KERN_ALERT "DEBUG: Passed %s %d \n",__FUNCTION__,__LINE__);

每次指定等级宏很麻烦，所以一般采用内核提供的另外一套api，pr_xxx来实现打印，它们对printk进行了简单的封装:

#define pr_emerg(fmt, ...) \
	printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
#define pr_alert(fmt, ...) \
	printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
#define pr_crit(fmt, ...) \
	printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
#define pr_err(fmt, ...) \
	printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
#define pr_warning(fmt, ...) \
	printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
#define pr_warn pr_warning
#define pr_notice(fmt, ...) \
	printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
#define pr_info(fmt, ...) \
	printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
#define pr_cont(fmt, ...) \
	printk(KERN_CONT fmt, ##__VA_ARGS__)
/* pr_devel() should produce zero code unless DEBUG is defined */
#ifdef DEBUG
#define pr_devel(fmt, ...) \
	printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
#define pr_devel(fmt, ...) \
	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#endif

#include <linux/dynamic_debug.h>

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

上面有几个地方需要注意：

1. DEBUG宏会影响pr_devel和pr_debug，当没有定义DEBUG的时候，那么实际不输出任何东西。pr_debug同时还会受CONFIG_DYNAMIC_DEBUG的影响，这个是配置内核动态debug的，具体使用方法，后面会进一步说明；
2. 当我们写设备驱动的时候，建议用dev_dbg替换pr_devel和pr_debug；
3. pr_cont用在综合多个打印的情况，比如前面的打印都没有\n来使能输出，最后通过pr_cont来将它们一起输出（Important Note: KERN_CONT and pr_cont should only be used by core/arch code during early bootup (a continued line is not SMP-safe otherwise)），它的应用场景举例：

KERN_CONT and pr_cont are special cases since they do not specify an urgency but rather indicate a 'continued message' e.g.:

printk(KERN_ERR "Doing something was ");
/* <100 lines of whatever>*/
if (success)
   printk(KERN_CONT "successful\n");
else
   printk(KERN_CONT "NOT successful\n");

我们在系统起来后，也可以临时的修改系统的默认等级，查看等级：

$ cat /proc/sys/kernel/printk
	7       4       1       7
	current	default	minimum	boot-time-default

我们可以通过如下命令来修改默认等级：

sudo sh -c "echo 8 > /proc/sys/kernel/printk"

或者

sudo sysctl -w kernel.printk=8

修改后，如下：

$ cat /proc/sys/kernel/printk
	8	4	1	7
	current	default	minimum	boot-time-default

这个只是临时修改，如果想永久有效，可以采用两种方式：

第一，通过命令行参数loglevel

	loglevel=	All Kernel Messages with a loglevel smaller than the
			console loglevel will be printed to the console. It can
			also be changed with klogd or other programs. The
			loglevels are defined as follows:

			0 (KERN_EMERG)		system is unusable
			1 (KERN_ALERT)		action must be taken immediately
			2 (KERN_CRIT)		critical conditions
			3 (KERN_ERR)		error conditions
			4 (KERN_WARNING)	warning conditions
			5 (KERN_NOTICE)		normal but significant condition
			6 (KERN_INFO)		informational
			7 (KERN_DEBUG)		debug-level messages

第二，手动编辑/etc/sysctl.conf里面的kernel.printk = 3 4 1 3，修改第一个值并保存即可。

问题2：内核崩溃过早时printk

这个的解决办法就是采用内核提供的early_printk替代printk。不过由于该机制和具体的平台相关，有些平台支持，有些平台不支持。幸运的是arm和x86都支持^_。要想使用该功能，需要做两个动作：

1. 配置CONFIG_EARLY_PRINTK，通过make menuconfig -> Kernel Hacking -> Early printk
2. 对于arm，需要在命令行上添加earlyprintk，对于x86，需要在命令行上添加earlyprintk=xxx，比如earlyprintk=serial,uart0,57600（请参考setup_early_printk函数）。x86上还可以采用earlycon方式，这个没用过，不过和earlyprintk类似，但它主要是通过8250输出，而earlyprintk在x86下支持serial、ttyS、vga等等。在arm下earlyprintk对应的数据结构里的name就叫earlycon

问题3：printk buffer size

这部分直接摘抄了：

Printk is implemented by using a ring buffer in the kernel with a size of `__LOG_BUF_LEN` bytes where `__LOG_BUF_LEN` equals (1 << `CONFIG_LOG_BUF_SHIFT`) (see kernel/printk.c for details).

You can specify the size of the buffer in your kernel config by setting `CONFIG_LOG_BUF_SHIFT `to an appropriate value (e.g. 17 for 128Kb) (make menuconfig -> General Setup -> Kernel log buffer size).

Using a ring buffer implies that older messages get overwritten once the buffer fills up, but this is only a minor drawback compared to the robustness of this solution (i.e. minimum memory footprint, callable from every context, not many resources wasted if nobody reads the buffer, no filling up of disk space/ram when some kernel process goes wild and spams the buffer, ...). Using a reasonably large buffer size should give you enough time to read your important messages before they are overwritten.

Note: dmesg reads by default a buffer of max 16392 bytes, so if you use a larger logbuffer you have to invoke dmesg with the -s parameter e.g.:

### CONFIG_LOG_BUF_SHIFT 17 = 128k
$ dmesg -s 128000

The kernel log buffer is accessible for reading from userspace by /proc/kmsg. /proc/kmsg behaves more or less like a FIFO and blocks until new messages appear.


Please note - reading from /proc/kmsg consumes the messages in the ring buffer so they may not be available for other programs. It is usually a good idea to let klogd or syslog do this job and read the content of the buffer via dmesg. 



Printk from userspace

Sometimes, especially when doing automated testing, it is quite useful to insert some messages in the kernel log buffer in order to annotate what's going on.

It is as simple as

# echo "Hello Kernel-World" > /dev/kmsg

Of course this messages gets the default log level assigned, if you want e.g. to issue a KERN_CRIT message you have to use the string representation of the log level - in this case "2"

# echo "2Writing critical printk messages from userspace" >/dev/kmsg

The message will appear like any other kernel message - there is no way to distinguish them!

Note: Don't confuse this with printf - we are printing a kernel message from userspace here.

If /dev/kmsg does not exist, it can be created with: 'mknod -m 600 /dev/kmsg c 1 11' 

其他一些printk的扩展api

printk_once
pr_emerg_once
pr_alert_once
pr_crit_once
pr_err_once
pr_warn_once
pr_notice_once
pr_info_once
pr_cont_once
pr_devel_once
pr_debug_once

printk_ratelimited 对应头文件#include <kernel/ratelimit.h> 及相关proc文件/proc/sys/kernel/printk_ratelimit(可以看作一个监测周期，在这个周期内只能发出下面的控制量的信息)和/proc/sys/kernel/printk_ratelimit_burst(以上周期内的最大消息数，如果超过了printk_ratelimit()返回0)
pr_emerg_ratelimited
pr_alert_ratelimited
pr_crit_ratelimited
pr_err_ratelimited
pr_warn_ratelimited
pr_notice_ratelimited
pr_info_ratelimited
pr_devel_ratelimited
pr_debug_ratelimited

hex_dump_to_buffer
print_hex_dump
print_hex_dump_bytes
print_hex_dump_debug

dev_emerg
dev_alert
dev_crit
dev_err
dev_warn
dev_notice
dev_info
dev_dbg

dev_emerg_ratelimited
dev_alert_ratelimited
dev_crit_ratelimited
dev_err_ratelimited
dev_warn_ratelimited
dev_notice_ratelimited
dev_info_ratelimited
dev_dbg_ratelimited

动态debug

这部分也直接摘抄吧，自己没做验证：

refs:

http://lwn.net/Articles/434833/

https://www.kernel.org/doc/Documentation/dynamic-debug-howto.txt


= Use dynamic debug(ddebug) =

==config==

enabe debugfs, enable CONFIG_DYNAMIC_DEBUG

for some subsystem which debug based on ddebug, e.g. xhci_dbg, you also need to enable subsystem's debug


==usage==

mount -t debugfs none /sys/kernel/debug

echo 8 > /proc/sys/kernel/printk

echo "file xx.c line xxx +p" > /sys/kernel/debug/dynamic_debug/control

#also has other support to enable debug info, check Documentation/dynamic-debug-howto.txt for details.

awk '$3 != "-" ' /sys/kernel/debug/dynamic_debug/control

#check the enabled debug info is same as expected or not.

OK. now run what you want to debug and get the info you care.

Enjoy it.

扩展阅读：Documentation / dynamic-debug-howto.txt

总结

这篇文章主要介绍了printk相关的一些东西，本来还想把其他的调试方法都往里面放的，但是写完printk后，自己也感叹了，这么个基础的小技巧居然也这么多需要注意的，于是就放弃了那个念头，让它独立吧！ ^_

参考

• 内核日志及printk结构浅析
• 跟我学系列-移植内核必备知识-对linux的early printk的探讨
• Debugging_by_printing
• Linux earlyprintk/earlycon support on ARM

完！
2015年12月