Linux内核pr_debug的应用及log级别控制原理简析
调试环境------
CPU：freescale i.mx6
操作系统：Linux
内核版本号：3.0.35
最近在调试一个spi nor flash芯片的时候用到了gpio倒出的功能，就是可以在linux起来以后，通过串口倒出，并可以控制输入输出方向和高低电平的一种功能。配置好对应的pin后发现怎么都不能在/sys/class/gpio的目录下生成相应的接口目录，我要倒出的GPIO是gpio bank6的第11教，根据imx6平台gpio编号的计算方法IMX_GPIO_NR(6, 11)，得到这个GPIO的编号是174（有兴趣的同学可以再imx6的平台代码上查看IMX_GPIO_NR这个宏的实现方法），通过如下命令实现倒出：
echo 174 > /sys/class/gpio/export
如果顺利倒出的话，会在gpio目录下生成gpio174这样的目录（/sys/class/gpio/gpio174），这个目录底下的接口可以对相应的gpio进行控制
执行了上述命令以后，没有生成gpio174这个目录，只好查看gpio_export函数实现，大概看了一下，整个倒出过程在关键步骤加了pr_debug调用，要用这个宏打印log可以通过DEBUG宏打开，具体打开方法如下：
1. 在内核根目录执行makemenuconfig
2. 进入内核配置图形界面以后查找
3. 退回到根菜单进入
4. 重新编译uImage，烧录
5. 现在还不能实现pr_debug的打印，还要降低prink的打印级别：
echo 8 > /proc/sys/kernel/printk
再执行gpio倒出，于是打印了下面的log：
在代码/drivers/gpio/gpiolib.c中找到了这个错误打印的位置
if(status)
pr_debug("gpio_request:gpio-%d (%s) status %d\n",
gpio,label ? : "?", status);
在status不为0的情况下打印出来的，status是-16，经过查询-16是EBUSY的errorcode，EBUSY解释是：
#define EBUSY 16 /* Device or resource busy */
这个gpio可能是被哪个设备占用了，所以导致倒出失败，查bsp代码还真是，注释调以后让我来用，再编译运行果然成功了，看来这个pr_debug还是挺有用的。
但是printk的级别控制引起了我的好奇心，为什么echo比7大的数值才能使用pr_debug呢？带着这个疑问开始看printk相关的内核代码:
先从printk的读写控制入手，看看proc文件系统中是怎么实现对printk节点进行读写的:
/fs/proc/proc_sysctl.c中proc_sys_init函数建立/proc/sys/目录，kernel目录是在/kernel/sysctl.c中structctl_table root_table中定义的，具体定义如下：
static struct ctl_table root_table[] = {
{
.procname = "kernel",
.mode = 0555,
.child = kern_table,
},
kern_table包含了一对kernel目录下的子节点的定义，当然也包含了printk节点的定义：
{
/* 节点名称 */
.procname = "printk",
/* 控制台log等级 */
.data = &console_loglevel,
.maxlen = 4*sizeof(int),
/* 节点权限 */
.mode = 0644,
/* 操作节点的回调函数 */
.proc_handler = proc_dointvec,
},
其中有两个变量是比较重要的console_loglevel保存log级别，其中/kernel/printk.c源码中有如下定义：
#defineMINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */
#defineDEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */
intconsole_printk[4] = {
DEFAULT_CONSOLE_LOGLEVEL, /* console_loglevel */
DEFAULT_MESSAGE_LOGLEVEL, /* default_message_loglevel */
MINIMUM_CONSOLE_LOGLEVEL, /* minimum_console_loglevel */
DEFAULT_CONSOLE_LOGLEVEL, /* default_console_loglevel */
};
头文件/inclue/linux/printk.h对console_loglevel做了定义：
#defineconsole_loglevel (console_printk[0])
#definedefault_message_loglevel (console_printk[1])
#defineminimum_console_loglevel (console_printk[2])
#definedefault_console_loglevel (console_printk[3])
可以看到console_loglevel的值默认为7
proc_handler变量保存的函数指针proc_dointvec做了操作节点的工作，调用过程是 proc_dointvec->do_proc_dointvec->__do_proc_dointvec, 这个调用过程是多个kernel目录下的节点共用的，我以printk为例说明一下log级别是如何别改写的：
/* tbl_data是data变量，printk的话也就是console_loglevel地址 */
static int __do_proc_dointvec(void*tbl_data, struct ctl_table *table,
/* write是读写标志， buffer是内核与用户空间交换数据的缓冲区，属于用户空间 */
int write, void __user *buffer,
/* lenp buffer长度指针 */
size_t *lenp, loff_t *ppos,
/* conv最终实现读写操作的函数指针，negp正负数标志，lvalp要写入的数据指针，valp目标地址指针， write读写标志， data传入NULL不必关心*/
int (*conv)(bool *negp, unsigned long *lvalp,int *valp,
int write, void *data),
/*data传入NULL不必关心 */
void *data)
{
int*i, vleft, first = 1, err = 0;
unsignedlong page = 0;
size_tleft;
char*kbuf;
if(!tbl_data || !table->maxlen || !*lenp || (*ppos && !write)) {
*lenp= 0;
return0;
}
/*console_loglevel的地址指针存入局部指针整型指针变量i中 */
i= (int *) tbl_data;
/*console_logleve所在数组元素数量，也就是console_printk元素数量，我们知道是4 */
vleft= table->maxlen / sizeof(*i);
/* 传入用户buffer长度 */
left= *lenp;
if(!conv)
/* 实际实现读写操作的函数指针赋值 */
conv= do_proc_dointvec_conv;
if(write) {
if(left > PAGE_SIZE - 1)
left= PAGE_SIZE - 1;
page= __get_free_page(GFP_TEMPORARY);
/* 内核buffer获取空间 */
kbuf= (char *) page;
if(!kbuf)
return-ENOMEM;
/* 把用户空间传入的数据传入内核buffer中，如果执行的是echo 8到printk中，kbuf中保存的就是整数8的字节表示 */
if(copy_from_user(kbuf, buffer, left)) {
err= -EFAULT;
gotofree;
}
kbuf[left]= 0;
}
for(; left && vleft--; i++, first=0) {
unsignedlong lval;
boolneg;
/* 读写操作的判断 */
if(write) {
/* 写操作 */
/* 去掉多余的空格，并减去相应的去掉字符数量 */
left-= proc_skip_spaces(&kbuf);
/* 如果写操作完直接跳出for循环 */
if(!left)
break;
/* 转换kbuf为无符号长整型数值，并存入lval中，记录正负标志 */
err= proc_get_long(&kbuf, &left, &lval, &neg,
proc_wspace_sep,
sizeof(proc_wspace_sep), NULL);
if(err)
break;
/* 把lval的值改写到console_loglevel变量中，i是console_loglevel地址上面已经介绍 */
if(conv(&neg, &lval, i, 1, data)) {
err = -EINVAL;
break;
}
}else {
/* 读操作 */
/* 把i地址存储的值读入到lval中 */
if(conv(&neg, &lval, i, 0, data)) {
err= -EINVAL;
break;
}
if(!first)
/* 如果不是第一个数字就加入一个tab符号到用户buffer中，cat /proc/sys/kernel/printk节点的话就是打印”7 4 1 7”的效果 */
err= proc_put_char(&buffer, &left, ‘\t‘);
if(err)
break;
/* 把lval放入用户buffer中 */
err= proc_put_long(&buffer, &left, lval, neg);
if(err)
break;
}
}
if(!write && !first && left && !err)
err= proc_put_char(&buffer, &left, ‘\n‘);
if(write && !err && left)
left-= proc_skip_spaces(&kbuf);
free:
if(write) {
free_page(page);
if(first)
returnerr ? : -EINVAL;
}
*lenp-= left;
*ppos+= *lenp;
returnerr;
}
static int do_proc_dointvec_conv(bool*negp, unsigned long *lvalp,
int *valp,
int write, void *data)
{
if(write) {
/* console_loglevel在这里被改写的，这个最关键的，log level根据这个值进行判断 */
*valp = *negp ? -*lvalp : *lvalp;
}else {
intval = *valp;
/* 读取console_printk的元素值，每次for循环valp都是下一元素的地址*/
if(val < 0) {
*negp= true;
*lvalp= (unsigned long)-val;
}else {
*negp= false;
*lvalp= (unsigned long)val;
}
}
return0;
}
上面是对console_loglevel读写的操作，下面来看一下printk真正的级别控制是怎么样实现的，在include/linux/printk.h中对pr_debug的定义
#if defined(DEBUG)
#define pr_debug(fmt, ...) \
/* KERN_DEBUG是内核打印级别，也就是7 */
printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#elif 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__)
#else
#define pr_debug(fmt, ...) \
no_printk(KERN_DEBUGpr_fmt(fmt), ##__VA_ARGS__)
#endif
如何定义了DEBUG宏呢？，上面选中了DEBUGGPIO calls选项，也就是打开了CONFIG_DEBUG_GPIO这个宏，/drivers/gpio/Makefile中根据这个宏加入了DEBUG宏的定义
也就是gpio driver包含pirntk.h头文件后自动打开DEBUG宏，下面看printk函数的实现，代码位置是kernel/printk.c：
asmlinkage int printk(const char *fmt, ...)
{
va_listargs;
intr;
#ifdef CONFIG_KGDB_KDB
if(unlikely(kdb_trap_printk)) {
va_start(args,fmt);
r= vkdb_printf(fmt, args);
va_end(args);
returnr;
}
#endif
va_start(args,fmt);
/*最终调用vprintk实现打印功能 */
r= vprintk(fmt, args);
va_end(args);
returnr;
}
vprintk实现：
asmlinkage int vprintk(const char *fmt,va_list args)
{
intprinted_len = 0;
/* 先复制当前log级别为缺省的默认消息级别，也就是4 */
intcurrent_log_level = default_message_loglevel;
unsignedlong flags;
intthis_cpu;
char*p;
size_tplen;
charspecial;
boot_delay_msec();
printk_delay();
preempt_disable();
/*This stops the holder of console_sem just where we want him */
raw_local_irq_save(flags);
this_cpu= smp_processor_id();
/*
* Ouch, printk recursed into itself!
*/
if(unlikely(printk_cpu == this_cpu)) {
/*
* If a crash is occurring during printk() onthis CPU,
* then try to get the crash message out butmake sure
* we can‘t deadlock. Otherwise just return toavoid the
* recursion and return - but flag therecursion so that
* it can be printed at the next appropriatemoment:
*/
if(!oops_in_progress) {
recursion_bug= 1;
gotoout_restore_irqs;
}
zap_locks();
}
lockdep_off();
spin_lock(&logbuf_lock);
printk_cpu= this_cpu;
if(recursion_bug) {
recursion_bug= 0;
strcpy(printk_buf,recursion_bug_msg);
printed_len= strlen(recursion_bug_msg);
}
/*Emit the output into the temporary buffer */
/* 按fmt格式化要打印字符串到printk_buf中，并返回长度 */
printed_len+= vscnprintf(printk_buf + printed_len,
sizeof(printk_buf) - printed_len, fmt, args);
p= printk_buf;
/* Read log level and handle special printk prefix */
/* 获取printk中加入的打印级别前缀，pr_debug加入的是KERN_DEBUG，也就是7，并返回代表打印级别的字符串长度,例<7>,长度是3 */
plen = log_prefix(p, ¤t_log_level, &special);
if(plen) {
p+= plen;
switch(special) {
case‘c‘: /* Strip <c> KERN_CONT, continue line */
plen= 0;
break;
case‘d‘: /* Strip <d> KERN_DEFAULT, start new line */
plen= 0;
default:
if(!new_text_line) {
emit_log_char(‘\n‘);
new_text_line= 1;
}
}
}
/*
* Copy the output into log_buf. If the callerdidn‘t provide
* the appropriate log prefix, we insert themhere
*/
for(; *p; p++) {
if(new_text_line) {
new_text_line= 0;
if(plen) {
/*Copy original log prefix */
/*printk_buf已经包含了传入的log级别字符串 */
inti;
for(i = 0; i < plen; i++)
/* 把要打印的字符串放入log_buf中 */
emit_log_char(printk_buf[i]);
printed_len+= plen;
}else {
/* Add log prefix */
/* 在printk特殊的应用时传入的并不是打印级别，这时候默认的log打印级别为4*/
emit_log_char(‘<‘);
emit_log_char(current_log_level+ ‘0‘);
emit_log_char(‘>‘);
printed_len+= 3;
}
if(printk_time) {
/*Add the current time stamp */
chartbuf[50], *tp;
unsignedtlen;
unsignedlong long t;
unsignedlong nanosec_rem;
t= cpu_clock(printk_cpu);
nanosec_rem= do_div(t, 1000000000);
tlen= sprintf(tbuf, "[%5lu.%06lu] ",
(unsignedlong) t,
nanosec_rem/ 1000);
for(tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len+= tlen;
}
if(!*p)
break;
}
emit_log_char(*p);
if(*p == ‘\n‘)
new_text_line= 1;
}
/*
* Try to acquire and then immediately releasethe
* console semaphore. The release will do allthe
* actual magic (print out buffers, wake upklogd,
* etc).
*
* The console_trylock_for_printk() function
* will release ‘logbuf_lock‘ regardless ofwhether it
* actually gets the semaphore or not.
*/
if(console_trylock_for_printk(this_cpu))
/* 关键函数 */
console_unlock();
lockdep_on();
out_restore_irqs:
raw_local_irq_restore(flags);
preempt_enable();
returnprinted_len;
}
/* 打印级别的判断和实际打印操作要通过下面一系列函数调用*/
console_unlock->call_console_drivers->_call_console_drivers
static void call_console_drivers(unsignedstart, unsigned end)
{
unsignedcur_index, start_print;
staticint msg_level = -1;
BUG_ON(((int)(start- end)) > 0);
cur_index= start;
start_print= start;
while(cur_index != end) {
if(msg_level < 0 && ((end - cur_index) > 2)) {
/*strip log prefix */
/* 在log_bug中获取传入的打印级别，以pr_debug为例就是7 */
cur_index +=log_prefix(&LOG_BUF(cur_index), &msg_level, NULL);
start_print= cur_index;
}
while(cur_index != end) {
charc = LOG_BUF(cur_index);
cur_index++;
if(c == ‘\n‘) {
if(msg_level < 0) {
/*
* printk() has already given us loglevel tagsin
* the buffer. This code is here in case the
* log buffer has wrapped right round andscribbled
* on those tags
*/
/* 如果没有传入打印级别，使用默认值4 */
msg_level= default_message_loglevel;
}
_call_console_drivers(start_print,cur_index, msg_level);
msg_level= -1;
start_print= cur_index;
break;
}
}
}
_call_console_drivers(start_print,end, msg_level);
}
static void _call_console_drivers(unsignedstart,
unsignedend, int msg_log_level)
{
/* 如果printk传入的打印级别小于console_loglevel，或者忽略打印级别满足打印条件ignore_loglevel，pr_debug传入的级别是7， console_loglevel 默认值也是7，所以在执行echo 8 > /proc/sys/kernel/printk中，pr_debug就可以打印出来了，根据上面的printk节点的说明，echo动作直接改写了console_loglevel的值，满足了 msg_log_level < console_loglevel这个条件 */
if((msg_log_level < console_loglevel ||ignore_loglevel) &&
console_drivers&& start != end) {
if((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
/*wrapped write */
__call_console_drivers(start& LOG_BUF_MASK,
log_buf_len);
__call_console_drivers(0,end & LOG_BUF_MASK);
}else {
__call_console_drivers(start,end);
}
}
}
好了，上面就是printk log级别控制的大致过程。