嵌入式Linux——printk:printk打印机制分析

时间:2021-12-26 20:23:50

简介:

    本文主要介绍printk打印机制,并结合内核代码分析其打印的原理。

 Linux内核:linux-2.6.22.6

 所用开发板:JZ2440 V3(S3C2440A)

声明:

    韦东山老师的驱动调试视频让我对printk机制有了更深刻的了解,以前我只是在写驱动的时候用到了printk,认为他其实就是与printf一样的一个打印的函数。但当我对printk函数分析过后我发现他们还是有区别的。而具体的区别我会在文中介绍。

printk代码分析:

    下面我们直接从printk的代码开始分析来了解printk的打印机制(而同时我会在分析代码时会补充一些其他的知识点)。

/**
 * printk - 打印内核信息
 * @fmt: 字符串格式
 *
 * printk函数可以被任何上下文调用。在printk中我们试着去获取控制台的信号量。如果我们成功了,那么我们将记录输出信息同时调用控制台驱动。
 * 如果我们成功了,那么我们将记录输出信息同时调用控制台驱动。如果我们失败,我们将输出信息放到log_buf中然后返回。
 * 控制台信号量的当前拥有者将注意到在release_console_sem()函数中新的输出信息,将他们在释放之前输出到控制台。
 *
 * See also:
 * printf(3)
 */

asmlinkage int printk(const char *fmt, ...)
{
	va_list args;
	int r;

	va_start(args, fmt);   //将fmt后的参数信息保存到args中
	r = vprintk(fmt, args); 
	va_end(args); //将参数args设为0  

	return r;
}

    我很注重看一个函数上面的注释,因为这个注释可以告诉我们很多有用的信息。比如上面的注释中我们知道了,printk主要做两件事情:第一件就是将信息记录到log中,而第二件事就是调用控制台驱动来将信息输出。所以我们在下面的分析代码时就有了方向,即从上面两个方向找相应的代码并做相关的说明。而从printk的代码中我们并没有看到上面说的这两件事,那么这些代码一定在最主要的vprintk函数里了。

vprintk函数由于分析的需要我会删除一些代码):

asmlinkage int vprintk(const char *fmt, va_list args)
{
	unsigned long flags;
	int printed_len;
	char *p;
	static char printk_buf[1024];   //从这里看printk_buf的大小为1k
	static int log_level_unknown = 1;

	preempt_disable();  //禁止内核抢占

	/* 禁止本地中断,加自旋锁 */
	raw_local_irq_save(flags);
	lockdep_off();
	spin_lock(&logbuf_lock);
	printk_cpu = smp_processor_id();

	/* 将输出信息放到printk_buf中,并返回放入字符的个数 */
	printed_len = vscnprintf(printk_buf, sizeof(printk_buf), fmt, args);

	/*
	 * 将输出信息从printk_buf中拷贝到log_buf中。
	 * 如果调用者没有为输出信息提供合适的日志级别,我们将为他设置默认的日志级别。
	 */
	for (p = printk_buf; *p; p++) {
		if (log_level_unknown) {   //如果日志级别未知,即没有设定
                        /* 在一行的开始位置没有发现日志级别信号 */
			if (printk_time) {
				int loglev_char;
				char tbuf[50], *tp;
				unsigned tlen;
				unsigned long long t;
				unsigned long nanosec_rem;

				/*
				 * 强制添加日志级别
				 */
				if (p[0] == '<' && p[1] >='0' &&
				   p[1] <= '7' && p[2] == '>') {
					loglev_char = p[1];
					p += 3;
					printed_len -= 3;
				} else {
					loglev_char = default_message_loglevel
						+ '0';
				}
				t = printk_clock(); //获得时钟信息
				nanosec_rem = do_div(t, 1000000000);
				tlen = sprintf(tbuf,
						"<%c>[%5lu.%06lu] ",
						loglev_char,
						(unsigned long)t,
						nanosec_rem/1000);

				for (tp = tbuf; tp < tbuf + tlen; tp++)  //将时钟信息写入到log_buf中
					emit_log_char(*tp);
				printed_len += tlen;
			} else {
				if (p[0] != '<' || p[1] < '0' ||
				   p[1] > '7' || p[2] != '>') {    //将日志级别写入log_buf中
					emit_log_char('<');
					emit_log_char(default_message_loglevel
						+ '0');
					emit_log_char('>');
					printed_len += 3;
				}
			}
			log_level_unknown = 0; 
			if (!*p)
				break;
		}
		emit_log_char(*p);   //将信息按字节写入log_buf中
		if (*p == '\n')
			log_level_unknown = 1;
	}
        //上面已完成第一件事:将信息写入log_buf中。下面就要做第二件事:调用控制台驱动
	if (!down_trylock(&console_sem)) {  //而我们在做第二件事之前要先获得控制台的信号量
		/*
		 * 我们获得了控制台信号量,可以拉低自旋锁,然后用release_console_sem()函数来打印输出信息。
		 */
		console_locked = 1;
		printk_cpu = UINT_MAX;
		spin_unlock(&logbuf_lock);

		/*
		 * Console drivers may assume that per-cpu resources have
		 * been allocated. So unless they're explicitly marked as
		 * being able to cope (CON_ANYTIME) don't call them until
		 * this CPU is officially up.
		 *///函数cpu_online检测CPU是否在线,函数have_callable_console()检测是否有注册的控制台启动时就可以使用
		if (cpu_online(smp_processor_id()) || have_callable_console()) {
			console_may_schedule = 0;
			release_console_sem();
		} else {
			/* 释放锁避免刷新缓冲区 */
			console_locked = 0;
			up(&console_sem);
		}
		lockdep_on();
		raw_local_irq_restore(flags);
	} else {
		/*
		 * 当我们不能获得控制台信号量时,我们拉低自旋锁来让信号量持有者来处理以及调用控制台驱动
		 */
		printk_cpu = UINT_MAX;
		spin_unlock(&logbuf_lock);
		lockdep_on();
		raw_local_irq_restore(flags);
	}
        //开启抢占机制
	preempt_enable(); 
	return printed_len;
}

    从上面看我们知道vprintk函数主要做了下面几件事:

1. 将输出信息放到printk_buf中,并返回放入字符的个数
2. 将输出信息从printk_buf中拷贝到log_buf中。
  a. 如果调用者别有为输出信息提供合适的日志级别,我们将为他设置默认的日志级别。
b. 将输出信息从printk_buf中拷贝到log_buf中。
3. 调用控制台驱动
a. 如果我们获得了控制台信号量,可以拉低自旋锁,然后用release_console_sem()函数来打印输出信息。
  b. 当我们不能获得控制台信号量时,我们拉低自旋锁来让信号量持有者来处理以及调用控制台驱动

    我们现在慢慢分析上面的几件事,对于第一件我们上面程序已经介绍的很清楚了。而我要强调的一点是在程序开始处的:

static char printk_buf[1024];

    从这里我们知道我们的printk_buf的大小为1024字节,所以我们在使用printk是要注意不要一次超出这个范围,不然的话可能造成内存溢出。

    下面我们看第二件事,我们先介绍一下日志级别,在我们内核中一共有8种级别,他们分别为:

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

    而在使用printk时我们会将日志级别放到最开始的位置,也就是上面程序中所指的第0位,第1位和第2位:

if (p[0] == '<' && p[1] >='0' && p[1] <= '7' && p[2] == '>') 

    而我们printk的使用也应该为:

printk(KERN_XXXXX"YYYYY");
    其中KERN_XXXXX表示的是上面的8种日志级别中的一种。而后面就是我们要输出的日志信息了。而这也是printk与printf的一个很大的区别, 那就是printk有日志级别 ,而我们会在后面根据日志的级别来判断他的日志信息是否可以输出。当然这要在之后的代码分析中介绍。

    现在我们还是回到我们的程序中,我们知道在写日志级别的信息里,日志级别会记录在我们的日志信息里,那么当我们没有写日志信息那该肿么办那?我们看程序:

				if (p[0] == '<' && p[1] >='0' &&
				   p[1] <= '7' && p[2] == '>') {
					loglev_char = p[1];
					p += 3;
					printed_len -= 3;
				} else {
					loglev_char = default_message_loglevel
						+ '0';
				}

    从上面程序中我们可以看出,当我们有日志级别时我们会将这个级别记录,而当我们没有时,我们会为他设一个默认的日志级别:default_message_loglevel。那么default_message_loglevel到底是多少那?我们接着看程序:

#define default_message_loglevel (console_printk[1])

int console_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 */
};

/* printk's without a loglevel use this.. */
#define DEFAULT_MESSAGE_LOGLEVEL 4 /* KERN_WARNING */
    从上面我们可以看出, 默认的日志级别为4

    好了,讲完日志级别,我们就要讲如何将输出信息放到log_buf这个环形缓冲区中了。我既然这样讲,大家可能就要问我几个问题了:

1. 怎么向这个log_buf中放入数据,或者以何种形式向log_buf中放入数据?

2. 怎么判断log_buf是个环形缓冲区?

3. log_buf这个环形缓冲区有多大?

    我一一回答上面的问题。第一输出信息时一个字节一个字节的放入到log_buf中的,而更详细的说明要看程序:

	for (p = printk_buf; *p; p++) {
		.................
		emit_log_char(*p);   //将信息按字节写入log_buf中
		if (*p == '\n')
			log_level_unknown = 1;
	}
    由于我们定义 char *p;所以我们是一个字节一个字节的写入到log_buf中的。

    现在我们回答第二个问题,要判断log_buf是不是环形缓冲区,这就要进入emit_log_char函数了:

static void emit_log_char(char c)
{
	LOG_BUF(log_end) = c;
	log_end++;
	if (log_end - log_start > log_buf_len)
		log_start = log_end - log_buf_len;
	if (log_end - con_start > log_buf_len)
		con_start = log_end - log_buf_len;
	if (logged_chars < log_buf_len)
		logged_chars++;
}

    从上面的代码中我们可能不好看出这是个环形缓冲区,那么我们看LOG_BUF(idx) 的宏定义以及log_start,log_end,con_start的定义

#define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK])
/*
 * The indices into log_buf are not constrained to log_buf_len - they
 * must be masked before subscripting
 */
static unsigned long log_start;	/* Index into log_buf: next char to be read by syslog() */
static unsigned long con_start;	/* Index into log_buf: next char to be sent to consoles */
static unsigned long log_end;	/* Index into log_buf: most-recently-written-char + 1 */

    从上面尤其是log_buf[(idx) & LOG_BUF_MASK]我们就可以看出这是个环形缓冲区。因为idx&LOG_BUF_MASK,当idx超出LOG_BUF_MASK时,他会忽略更高位的值,而从0开始。

    下面我们回答第三个问题,其实在上面我们已经介绍了第三个问题的答案,那就是LOG_BUF_MASK。因为当idx超过这个值时,log_buf要重新开始。所以LOG_BUF_MASK就是log_buf的最大容量了。而LOG_BUF_MASK是多少那?我们还是看程序:

#define LOG_BUF_MASK	(log_buf_len-1)
static int log_buf_len = __LOG_BUF_LEN;
#define __LOG_BUF_LEN	(1 << CONFIG_LOG_BUF_SHIFT)
#define CONFIG_LOG_BUF_SHIFT 16
    从上面看这个 log_buf的大小为2^16,也就是65536字节

    讲完这些我们就要讲在vprintk中做的第三件事:调用控制台驱动。而在这里我们假设我们获得了控制台信号量,那么我们最主要的就是分析release_console_sem()函数了。而这个函数也是这里的重点。

/**
 * release_console_sem - 解锁控制台系统
 *
 * 释放调用者持有的控制台系统信号量以及控制台驱动列表
 *
 * 当持有了信号量,控制台输出也被printk函数保存好了。
 * 如果是这样,我们发送输出优先级来释放信号量
 * 如果这里的输出为等待klogd,我们唤醒他
 *
 * release_console_sem() 可以在任意上下文中调用.
 */
void release_console_sem(void)
{
	unsigned long flags;
	unsigned long _con_start, _log_end;
	unsigned long wake_klogd = 0;

	if (console_suspended) {
		up(&secondary_console_sem);
		return;
	}

	console_may_schedule = 0;

	for ( ; ; ) {
		spin_lock_irqsave(&logbuf_lock, flags);
		wake_klogd |= log_start - log_end;
		if (con_start == log_end)
			break;			/* Nothing to print */
		_con_start = con_start;
		_log_end = log_end;
		con_start = log_end;		/* Flush */
		spin_unlock(&logbuf_lock);
		call_console_drivers(_con_start, _log_end);
		local_irq_restore(flags);
	}
	console_locked = 0;
	up(&console_sem);
	spin_unlock_irqrestore(&logbuf_lock, flags);
	if (wake_klogd)
		wake_up_klogd();
}

    从上面程序看,最主要的部分就是call_console_drivers函数,通过调用控制台驱动函数来释放信号量,而在此之前将输出信息通过控制台驱动发出。我们下面分析call_console_drivers函数:

/*
 * 调用控制台驱动来将从log_buf[start] 到log_buf[end - 1]的数据输出
 * 而完成这些的前提是拥有控制台信号量
 */
static void call_console_drivers(unsigned long start, unsigned long end)
{
	unsigned long cur_index, start_print;
	static int msg_level = -1;

	BUG_ON(((long)(start - end)) > 0);

	cur_index = start;
	start_print = start;
	while (cur_index != end) {  //遍历要传输的数据
		if (msg_level < 0 && ((end - cur_index) > 2) &&
				LOG_BUF(cur_index + 0) == '<' &&
				LOG_BUF(cur_index + 1) >= '0' &&
				LOG_BUF(cur_index + 1) <= '7' &&
				LOG_BUF(cur_index + 2) == '>') {   //判断日志级别是否大于等于0并小于等于7
			msg_level = LOG_BUF(cur_index + 1) - '0';
			cur_index += 3;
			start_print = cur_index;
		}
		while (cur_index != end) {
			char c = LOG_BUF(cur_index);

			cur_index++;
			if (c == '\n') {
				if (msg_level < 0) {  如果没有日志级别,为他设置默认值
					/*
					 * printk() has already given us loglevel tags in
					 * the buffer.  This code is here in case the
					 * log buffer has wrapped right round and scribbled
					 * on those tags
					 */
					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);
}

    函数_call_console_drivers将缓冲区中从start到end - 1的数据输出到控制台进行显示。在输出数据到控制台之前,它检查消息的日志级别。那么在_call_console_drivers函数中又做了什么那?

/*
 * 输出从start 到 end - 1 之间的信息
 */
static void _call_console_drivers(unsigned long start,
				unsigned long end, int msg_log_level)
{
	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);
		}
	}
}

    从上面第一个判断语句可以看出,只有当msg_log_level 小于 console_loglevel才可以将信息输出。这也是我们非常重要的一点,我们可以设置console_loglevel的值来显示我们想显示的级别的信息。而console_loglevel的值为7:

#define console_loglevel (console_printk[0])

int console_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 */
};

#define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */

    而由__call_console_drivers函数输出信息。

/*
 * 调用控制台驱动传输信息
 */
static void __call_console_drivers(unsigned long start, unsigned long end)
{
	struct console *con;

	for (con = console_drivers; con; con = con->next) {   //遍历控制台启动驱动  
		if ((con->flags & CON_ENABLED) && con->write &&
				(cpu_online(smp_processor_id()) ||
				(con->flags & CON_ANYTIME)))
			con->write(con, &LOG_BUF(start), end - start); //使用控制台驱动的write函数传输信息
	}
}

    从上面看要先找到注册好的控制台驱动,然后我们的控制台调用自己的write函数来完成输出符合要求的信息。如果我们的控制台是串口的控制台,那么我们的信息就从串口输出了。    

    讲到这里我们关于printk的程序就分析完了,但是我相信很多人可能对数据的输出还是不明白:不明白这个数据是怎么传输了?控制台的write函数是怎么实现的?以及如何来确定使用串口传输数据?

控制台的选择:

    带着上面的问题我们进入这个话题。我们从上面的程序看出只要选择好了console_driver之后我们才能调用他的write函数来将要输出的信息输出到特定的驱动上,所以我们在这里要确定我们要选择的是哪个console_driver ?同时我们也知道可以通过在uboot中设置bootargs中的console=XXX选项来选择我们要通过何种方式输出信息。例如:

当uboot的命令行里的“console=ttySAC1”时,表示printk()输出在开发板的LCD屏上

当uboot的命令行里的“console=ttySAC0,115200”时,表示printk()输出在串口UART0上,波特率=115200

当uboot的命令行里的“console=ttySAC1 console=ttySAC0,115200”时,表示printk()同时输出在串口上,以及开发板的LCD屏上

    但是我们要想知道具体的console_driver的选择过程,那就要从内核的代码中查找了,我们从init\main.c中的start_kernel函数看起:

asmlinkage void __init start_kernel(void)
	parse_early_param();
		parse_args("early options", tmp_cmdline, NULL, 0, do_early_param);    

    上面函数的递进层次表示在上面的函数中调用下层函数。我们知道既然bootargs中的参数可以选择console_driver的类型。那么我们在分析内核的初始化代码时就应该从这些uboot中传过来的参数开始找起。所以我们上面分析代码的思路就是去找与uboot中传来参数有关的函数。而当我们看到parse_args函数中与处理参数有关的函数do_early_param函数时,我们进去看他做了什么:

static int __init do_early_param(char *param, char *val)
{
	struct obs_kernel_param *p;

	for (p = __setup_start; p < __setup_end; p++) {
		if (p->early && strcmp(param, p->str) == 0) {
			if (p->setup_func(val) != 0)
				printk(KERN_WARNING
				       "Malformed early option '%s'\n", param);
		}
	}
	/* We accept everything at this stage. */
	return 0;
}

    上面函数中有一个非常重要的信息就是:for (p = __setup_start; p< __setup_end; p++) 即从__setup的开始找到__setup的结束,同时我们要调用__setup中设置函数p->setup_func(val)。。所以我们在这就要找与console相关的__set_up了。而我们从在kernel\printk.c中找到:

__setup("console=", console_setup);

    从上面的do_early_param函数我们知道,当我们从__set_up中找到相应的设置时我们就会调用他相关的函数,所以在console的__set_up中他对应的函数为:console_setup函数。我们进入这个函数:

/*
 * Set up a list of consoles.  Called from init/main.c
 */
static int __init console_setup(char *str)
{
	char name[sizeof(console_cmdline[0].name)];
	char *s, *options;
	int idx;

	/*
	 * 将str分为name,index以及options三部分
	 */
	if (str[0] >= '0' && str[0] <= '9') {
		strcpy(name, "ttyS");
		strncpy(name + 4, str, sizeof(name) - 5);
	} else {
		strncpy(name, str, sizeof(name) - 1);
	}
	name[sizeof(name) - 1] = 0;
	if ((options = strchr(str, ',')) != NULL)
		*(options++) = 0;

	for (s = name; *s; s++)
		if ((*s >= '0' && *s <= '9') || *s == ',')
			break;
	idx = simple_strtoul(s, NULL, 10);
	*s = 0;

	add_preferred_console(name, idx, options); 
	return 1;
}

    在上面函数中参数str就是我们在uboot中传入的参数console=XXX中的XXX,即真正的console_driver的名称。而上面函数的重点是add_preferred_console函数,我们进去看他做了什么:

/**
 * add_preferred_console - 添加一个设备到控制台列表
 * @name: device name
 * @idx: device index
 * @options: options for this console
 *
 * 最后的添加的一个控制台将用来为内核信息和标准输入/输出/错误的初始化。
 * 一般他都是由用户支持的console_setup控制台参数来设置。
 */
int __init add_preferred_console(char *name, int idx, char *options)
{
	struct console_cmdline *c;
	int i;

	/*
	 *	看这个tty是否注册
	 */
	for(i = 0; i < MAX_CMDLINECONSOLES && console_cmdline[i].name[0]; i++)
		if (strcmp(console_cmdline[i].name, name) == 0 &&
			  console_cmdline[i].index == idx) {
				selected_console = i;
				return 0;
		}
	if (i == MAX_CMDLINECONSOLES)
		return -E2BIG;
	selected_console = i;
	c = &console_cmdline[i];
	memcpy(c->name, name, sizeof(c->name));
	c->name[sizeof(c->name) - 1] = 0;
	c->options = options;
	c->index = idx;
	return 0;
}

    从上面的代码可以看出,这里主要是将我们的console信息注册到了一个console_cmdline的列表中。而对于如何从这个列表中获得console信息并调用相应的函数我们就要看是哪个函数使用到了console_cmdline列表并调用了他中console的相关信息。通过查找我们发现是在register_console函数中使用了console_cmdline列表。我们看在register_console函数中做了什么?

/*
 * 在内核初始化时,控制台驱动调用该程序来注册控制台打印处理以完成printk函数
 */
void register_console(struct console *console)
{
	int i;
	unsigned long flags;
	struct console *bootconsole = NULL;

	if (console_drivers) {
		if (console->flags & CON_BOOT)
			return;
		if (console_drivers->flags & CON_BOOT)
			bootconsole = console_drivers;
	}

	if (preferred_console < 0 || bootconsole || !console_drivers)
		preferred_console = selected_console;

	/*
	 * 看我们是否有设定console,如果没有我们将这里注册的第一个设为选定的
	 */
	if (preferred_console < 0) {
		if (console->index < 0)
			console->index = 0;
		if (console->setup == NULL ||
		    console->setup(console, NULL) == 0) {
			console->flags |= CON_ENABLED | CON_CONSDEV;
			preferred_console = 0;
		}
	}

	/*
	 *  看是否这个控制台与uboot命令行中的的控制台匹配
	 */
	for (i = 0; i < MAX_CMDLINECONSOLES && console_cmdline[i].name[0];
			i++) {
		if (strcmp(console_cmdline[i].name, console->name) != 0)
			continue;
		if (console->index >= 0 &&
		    console->index != console_cmdline[i].index)
			continue;
		if (console->index < 0)
			console->index = console_cmdline[i].index;
		if (console->setup &&
		    console->setup(console, console_cmdline[i].options) != 0)
			break;
		console->flags |= CON_ENABLED;
		console->index = console_cmdline[i].index;
		if (i == selected_console) {
			console->flags |= CON_CONSDEV;
			preferred_console = selected_console;
		}
		break;
	}

	if (!(console->flags & CON_ENABLED))
		return;

	if (bootconsole) {
		printk(KERN_INFO "console handover: boot [%s%d] -> real [%s%d]\n",
		       bootconsole->name, bootconsole->index,
		       console->name, console->index);
		unregister_console(bootconsole);
		console->flags &= ~CON_PRINTBUFFER;
	}

	/*
	 * 将这个控制台放入列表,并保持在上面add_preferred_console函数中的驱动在列表头,获得控制台信号量
	 */
	acquire_console_sem();
	if ((console->flags & CON_CONSDEV) || console_drivers == NULL) {
		console->next = console_drivers;
		console_drivers = console;
		if (console->next)
			console->next->flags &= ~CON_CONSDEV;
	} else {
		console->next = console_drivers->next;
		console_drivers->next = console;
	}
	if (console->flags & CON_PRINTBUFFER) {
		/*
		 * release_console_sem() will print out the buffered messages
		 * for us.
		 */
		spin_lock_irqsave(&logbuf_lock, flags);
		con_start = log_start;
		spin_unlock_irqrestore(&logbuf_lock, flags);
	}
	release_console_sem();
}

    从上面的程序中我们知道他主要做了下面几件事:

1. 看我们是否有设定console,如果没有我们将这里注册的第一个设为选定的
2. 看是否这个控制台与uboot命令行中的的控制台匹配
3. 将这个控制台放入列表,并保持在上面add_preferred_console函数中的驱动在列表头,获得控制台信号量

   我们从前面对printk的分析中知道,如果想调用一个控制台的write函数我们就要先获得这个控制台的信号量而上面函数就是获得信号量。

    从上面的对这个函数的注释我们知道,这个函数是被特定的控制台驱动调用的,只有调用了该函数才可以把我们在add_preferred_console中添加的console注册到列表中。那么我们下一步就要找是哪个控制台驱动调用了register_console函数。我们通过搜索发现了在drivers\serial\s3c2410.c中用到了这个函数:

嵌入式Linux——printk:printk打印机制分析

static int s3c24xx_serial_initconsole(void)
{
	struct s3c24xx_uart_info *info;
	struct platform_device *dev = s3c24xx_uart_devs[0];

	........................

	s3c24xx_serial_console.data = &s3c24xx_uart_drv;
	s3c24xx_serial_init_ports(info);

	register_console(&s3c24xx_serial_console);  //将s3c24xx_serial_console注册到了console列表中
	return 0;
}
    而上面函数最主要的就是将s3c24xx_serial_console注册到了console列表中。
    我们看 s3c24xx_serial_console里有什么:
static struct console s3c24xx_serial_console =
{
	.name		= S3C24XX_SERIAL_NAME,
	.device		= uart_console_device,
	.flags		= CON_PRINTBUFFER,
	.index		= -1,
	.write		= s3c24xx_serial_console_write,
	.setup		= s3c24xx_serial_console_setup
};

    上面的name为:S3C24XX_SERIAL_NAME

#define S3C24XX_SERIAL_NAME	"ttySAC"
    从这里看我们就知道在uboot中我们为什么要用console=ttySAC0来选择串口了。因为这里定义的name就是ttySAC。而我们console所调用的write函数就是:s3c24xx_serial_console_write函数了。

    我想讲到这里大家就都明白printk的具体操作过程了吧。我想上面的那些问题大家也就知道答案了。

日志级别的设置:

    我们既然说printk与printf的一个区别是,printk可以根据设置的日志级别来确定这个语句最后是否能够打印出来。那么我们是不是可以设置这些日志级别那?例如我们知道我们默认的日志级别为4,那么我们是否可以将其修改为其他的值那?

    答案是肯定的,因为我们分析代码过来知道可以直接修改内核源码来修改日志级别。我们可以将default_message_loglevel设为我们想设的值。同时我们也可以设置_call_console_drivers函数中第一个判断语句中console_loglevel的值,因为只有当日志级别小于这个值的时候我们才会将信息打印。所以设置这个值可以起到同样的效果。

    这是我们想到的第一个办法,但不是一个好的办法,因为内核代码的修改对于了解的人还好说,但是对于不了解的人那就容易出问题。同时内核源码既然这样设置,是有他的原因的我们不要去随便修改他。我要说的第二个办法就相对简单些,那就是在uboot的bootargs中加入“loglevel=X”的语句,而其他的语句不变。其中X就是我们想要设置的console_loglevel的值。他的实现原理其实跟设置“console=ttySAC0”一样。通过__setup来设置console_loglevel:

__setup("loglevel=", loglevel);

    具体代码我就不分析了。而同时我们会发现还有两个__setup的设置,他们的代码为:

__setup("debug", debug_kernel);
__setup("quiet", quiet_kernel);

    而他们的功能我们通过他们相应的函数设置函数可以知道就是分别将console_loglevel设为10和4 。他们的代码说明为:

static int __init debug_kernel(char *str)
{
	if (*str)
		return 0;
	console_loglevel = 10;
	return 1;
}

static int __init quiet_kernel(char *str)
{
	if (*str)
		return 0;
	console_loglevel = 4;
	return 1;
}

    这里主要介绍这两种,但是还有第三种,但是这种方法要在成功开启内核后才可以使用,那就是将要设置的值写入到/proc/sys/kernel/printk中。我们要先cat /proc/sys/kernel/printk来看一下这个文件中都有什么值。然后我们再写入。其中这里的格式为:控制台的日志级别、默认消息日志级别、最小控制台日志级别和默认控制台日志级别。而我们要设置的就是第一个控制台的日志级别。我们通过echo “W   X    Y    Z” > /proc/sys/kernel/printk 将我们想要设置的四个值写入到/proc/sys/kernel/printk中。

内核信息的输出:    

    既然介绍了设置日志级别,那么我们也应该介绍如何读取这些要输出的信息,或者存在log_buf中的信息。这里有两种方法,第一种是使用dmesg命令打印。第二种是通过cat /proc/kmsg来打印。他们其实最终都调用了/kernel/printk.c中的do_syslog函数,实现对__log_buf的访问及相关变量的修改。

    但值得注意的是: 从/proc/kmsg中获取数据,那么__log_buf中被读取过的数据就不再保留(也就是会修改log_start指针), 然而 syslog 系统调用返回日志数据并保留数据给其他进程。读取/proc文件是 klogd的默认做法。dmesg命令可用来查看缓存的内容并保留它,其实它是将__log_buf中的所有内容返回给stdout,并不管它是否已经被读取过。

    我在这里也贴出这张内核printk和日志系统的总体结构图,希望对大家有用:

嵌入式Linux——printk:printk打印机制分析

printk的运用:

    好了,介绍完这些我们就要讲一个printk在调试程序时的应用:

printk(KERN_DEBUG"%s %s %d\n", __FILE__, __FUNCTION__, __LINE__);
//__FILE__:    表示文件路径
//__FUNCTION__: 表示函数名
//__LINE__:    表示代码位于第几行
//KERN_DEBUG:   等于7,表示打印级别为7

    我们将上面的代码放到我们自己写的驱动程序中会打印出我们想要显示的信息。同时我们可以结合二分查找法,这样可以更快的将驱动中的错误信息定位出来。

参考文献:

关于printk的分析
内核日志:API 及实现
34.Linux-printk分析、使用__FILE__, __FUNCTION__, __LINE__ 调试
printk实现分析
[kernel]内核日志及printk结构分析
2.1.4 printk打印消息机制
linux printk工作原理