【原创】内核日志的打印格式

（转载请注明出处，发现问题请联系raymond_rule@hotmail.com）

　　在调试设备驱动时，使用dev_printk()是比较方便的。那么它到底是如何实现的呢？它会额外增加哪些打印信息呢？这些打印的信息以何种形式出现呢？

　　有时候在查看系统出错的log时，想以某个字符串作为关键字来grep一下，查找出错的原因时，费劲心机，甚至用上了通配符，都无法grep到打印的位置。这又是为什么呢？

　　本文将以dev_printk()为例，回答上述问题。

1. dev_printk()的基本调用流程

dev_printk()的基本用法如下：

　　 dev_printk(KERN_DEBUG, &bus->dev, "on NUMA node %d\n", node);

　　从调用来看，开发人员调用该函数的目的是打印“on NUMA node %d\n”，但是调用dev_printk()时，给出了&bus->dev参数，因此，dev_printk()额外打印的一些内容都是从该参数中提取的。

 

1.1 调用__dev_printk_emit()

 

　　调用dev_printk_emit()多打印了driver_string和dev_name两个信息，并且用冒号将新增的内容与开发人员想打印的内容分开。

 

1.2 调用dev_vprintk_emit()

　　dev_printk_emit()会保留原参数，直接调用dev_vprintk_emit()。

 

调用create_syslog_header()

　　创建属性字典（property dictionary），该函数名易让人混淆它的功能，看起来应该叫“create_property_dict()”较为合适。

首先是SUBSYSTEM信息：

 

然后是device identifier信息：即DEVICE=xxxxxx，其中xxxxxx的内容可能是：

　　* Add device identifier DEVICE=:

　　*   b12:8         block dev_t       // 主设备号不为0的block device

　　*   c127:3        char dev_t         // 主设备号不为0的char device

　　*   n8            netdev ifindex  // 除上述情况外，若是网络设备

　　*   +sound:card0  subsystem:devname // 除上述两种情况之外的其他设备

　　通过阅读kernel/printk/printk.c中的注释可知，属性字典的信息可以通过/dev/kmsg来查看。

调用vprintk_emit()

　　把调用create_syslog_header()创建的属性字典内容，连同开发人员指定要打印的信息一并传入vprintk_emit()。

vprintk_emit的行为是：

　　Step 1. 首先定义一段长为（1024-32）字节的buffer：static char textbuf[LOG_LINE_MAX];

　　Step 2. 把开发人员指定要打印的信息拷贝到Step 1中定义的buffer中

　　Step 3. 获得打印级别，并且把buffer指针text指向去掉打印级别字符串之后的字符串。

　　Step 4. 调用log_store()把属性字典以及开发人员指定的信息都写入到真正的打印缓冲区，并且更新缓冲区计数器。

说明：

　　1. Linux有多种方式从这个缓冲区中取内容打印到console以及写入日志文件，具体地可以查看log_buf的使用情况

　　2. 仔细观察写入log_buf中的内容，你会发现，该环形缓冲区里面的内容是三段结构：

printk_log结构

text content

dict结构（即header）

　　dict结构是在调用create_syslog_header()时创建的，那么为什么我们在系统的log文件中看不到这些信息呢？这是因为系统有选择地打印缓冲区的内容，并且也不是简单地把buffer中的内容完完整整地打印，而是经过加工处理之后，才打印到console或写到log文件中的。通过log_text()和log_dict()来分别获得text content和dict结构的指针。

 

2 神奇的“%”

　　分析完dev_printk()的基本调用流程，似乎还是看不懂某些内核日志，例如有如下格式的日志：

 

　　方括号以及方括号中的内容（[mem 0x…]）怎么打出来的呢？要想定位该打印语句的位置，就不是那么容易了。主要是因为使用了vsnprintf()函数，这个函数让人又爱又恨，爱的是它在字符串拼接方面非常好用，恨的是拼接之后的字符串不容易用grep定位。实际上，上面的log输出语句是：

　　　　　　dev_printk(KERN_DEBUG, &dev->dev, "reg 0x%x: %pR\n", pos, res);

　　在vprintk_emit()中，会调用vscnprintf()，进而调用vsnprintf()来把最初调用dev_printk()时指定的格式字符串拼接到textbuf中。以上面给出的打印语句为例，具体过程分析如下：

　　首先，解析dev_printk()中给出的格式字符，即以%作为开头的参数部分：

 

　　调用format_decode()解析%后面的部分，返回欲打印的类型以及打印类型关键字相对字符串开头的offset。

 

　　接下来在vsnprintf()中，首先把fmt指向%p的‘p’处，然后根据spec.type匹配到FORMAT_TYPE_PTR，进而调用pointer()来进行字符串的拼接：

 

在pointer()函数中匹配到‘R’：

 

　　匹配到“%pR”中的“R”，因此直接调用resource_string()，resource_string()的作用就是根据传入的resource*参数，组建出方括号部分内容，并存入buf中，这里的buf就是textbuf。

 

附注：vsnprintf()以及pointer()函数的注释。通过查看这些注释以及printk-formats.txt可以方便地了解各种log格式的情况。