Linux print system
linux中的调试方法有很多种,但我们最常用的也是最关键的调试工具应该就是使用print函数与console进行信息交互。在内核驱动的调试过程我们一般会使用内核提供的printk函数来进行调试,在应用层时我们会使用标准的c库函数printf,在shell脚本中我们会使用echo/logger等工具,接下来就让我们逐步了解这些工具吧。
1.内核printk函数工作原理
printk函数是内核提供的格式化打印函数,它几乎可以在内核的任意时刻使用(中断上下文、进程上下文、持有锁时、多处理器处理时)。但也有一些地方不能使用printk函数进行打印,如系统启动过程中和console_init之前,就不能直接调用printk,如果确实需要调试这段代码,内核提供了一个新的接口函数early_printk,需要我们在.config中将其打开,具体实现方式自行分析下,这边对printk函数进行具体分析。
printk的实现函数位于 kernel/printk.c
中(较新版本的内核位于kernel/printk/printk.c
中,原理一样),如下:
asmlinkage int printk(const char *fmt, ...)
{
va_list args;
int r;
va_start(args, fmt);
r = vprintk(fmt, args);
va_end(args);
return r;
}
va_start
和va_end
是在读取可变参数中常用的函数,主要就是将*fmt中的数据保存到args中,接着看vprintk(fmt, args)
函数,如下:
asmlinkage int vprintk(const char *fmt, va_list args)
{
int printed_len = 0;
int current_log_level = default_message_loglevel;
unsigned long flags;
int this_cpu;
char *p;
boot_delay_msec();
printk_delay();
/*关闭内核抢占*/
preempt_disable();
/*保存中断信息,获取cpu id*/
raw_local_irq_save(flags);
this_cpu = smp_processor_id();
/*
* Ouch, printk recursed into itself!
*/
/*CPU crash时的保护处理机制*/
if (unlikely(printk_cpu == this_cpu)) {
/*
* If a crash is occurring during printk() on this CPU,
* then try to get the crash message out but make sure
* we can't deadlock. Otherwise just return to avoid the
* recursion and return - but flag the recursion so that
* it can be printed at the next appropriate moment:
*/
if (!oops_in_progress) {
recursion_bug = 1;
goto out_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 */
/*将要输出的字符串放入printk_buf中,并返回字符长度*/
printed_len += vscnprintf(printk_buf + printed_len,
sizeof(printk_buf) - printed_len, fmt, args);
p = printk_buf;
/* Do we have a loglevel in the string? */
/*如果调用者没有提供合适的日志级别,则插入默认级别*/
if (p[0] == '<') {
unsigned char c = p[1];
if (c && p[2] == '>') {
switch (c) {
case '0' ... '7': /* loglevel */
current_log_level = c - '0';
/* Fallthrough - make sure we're on a new line */
case 'd': /* KERN_DEFAULT */
if (!new_text_line) {
emit_log_char('\n');
new_text_line = 1;
}
/* Fallthrough - skip the loglevel */
case 'c': /* KERN_CONT */
p += 3;
break;
}
}
}
/*
* Copy the output into log_buf. If the caller didn't provide
* appropriate log level tags, we insert them here
*/
/*拷贝printk_buf数据到环形缓冲区中,拷贝过程由函数emit_log_char实现,每次拷贝一个字节*/
for ( ; *p; p++) {
if (new_text_line) {
/* Always output the token */
emit_log_char('<');
emit_log_char(current_log_level + '0');
emit_log_char('>');
printed_len += 3;
new_text_line = 0;
if (printk_time) {
/* Follow the token with the time */
char tbuf[50], *tp;
unsigned tlen;
unsigned long long t;
unsigned long nanosec_rem;
t = cpu_clock(printk_cpu);
nanosec_rem = do_div(t, 1000000000);
tlen = sprintf(tbuf, "[%5lu.%06lu] ",
(unsigned long) 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 release the
* console semaphore. The release will do all the
* actual magic (print out buffers, wake up klogd,
* etc).
*
* The acquire_console_semaphore_for_printk() function
* will release 'logbuf_lock' regardless of whether it
* actually gets the semaphore or not.
*/
/*获取console结构的信号量*/
if (acquire_console_semaphore_for_printk(this_cpu))
/*将信息传给console驱动*/
release_console_sem();
lockdep_on();
out_restore_irqs:
/*恢复中断信息*/
raw_local_irq_restore(flags);
/*开启内核抢占*/
preempt_enable();
return printed_len;
}
vprintk函数比较长一点,但其执行的流程其实比较直观:
- 关闭内核抢占,保存中断信息;
- 将数据保存到临时缓冲
printk_buf
中,并将日志级别信息添加进buf,如果没定义则以默认的级别添加进去,注意printk_buf只有1KB; - 通过
emit_log_char()
函数将printk_buf
中的数据以一个一个char的形式传给log_buf; - 获取console信号量,然后调用
release_console_sem()
函数,该函数主要就是调用console驱动,将buf的内容通过console的write接口传输出去; - 最后就是恢复中断信息,打开内核抢占。
通过上面的流程我们应该已经了解printk函数的实现,不过还是有几个细节下面再提及:
1.环形缓冲区
环形缓冲区的定义#define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK])
,接着追踪下去,可以发现#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
,其中CONFIG_LOG_BUF_SHIFT
用来限制环形缓冲区的大小,默认是17,即128KB,可以在.config中进行配置调整。
这边的log_buf(128KB)
和上面的printk_buf(1KB)
是不一样的,printk_buf
更像是临时缓冲区,每次调用printk函数最大量是1KB,当重新调用printk函数时会将上次的清空,写入新的数据到printk_buf
,log_buf
是一个环形缓冲区,它的数据是printk_buf
给它的,但是当新的数据写入时,原本的数据不会被清空,而是一直往后写,当log_buf写满128KB时就环形写入,从头部开始覆盖写入。
2.emit_log_char()函数
该函数实现的是每次写入一个字符,即对于每一个字符的赋值log_end则只管++,在加一之后进行判断,如果log_end的值大于log_start,则表示缓冲区的长度已经达到最大,下一次的写入就将覆盖之前最旧的位置,因此log_start = log_end - log_buf_len
,将log_start的位置向后移一位(因为每次只写入一个字符,不可能超过一位)实现环形缓存区,代码如下:
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++;
}
3.release_console_sem()函数
该函数完成console相关的操作,主要过程就是将con_start
与log_end
间的数据通过call_console_drivers()
函数来完成数据往console的传递,并且在最后环形klogd进程。
void release_console_sem(void)
{
unsigned long flags;
unsigned _con_start, _log_end;
unsigned wake_klogd = 0;
if (console_suspended) {
up(&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);
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(_con_start, _log_end);
start_critical_timings();
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
函数,该函数指向struct console *con;
设备,最终通过设备写函数,进行写如数据,如下:
static void __call_console_drivers(unsigned start, unsigned end)
{
struct console *con;
for_each_console(con) {
if ((con->flags & CON_ENABLED) && con->write &&
(cpu_online(smp_processor_id()) ||
(con->flags & CON_ANYTIME)))
con->write(con, &LOG_BUF(start), end - start);
}
}
至此printk函数的实现流程已经完成,当然中间有很多细节之处还不是很了解,需要进一步深入。
2.内核printk函数打印优先级
上面我们提到了printk函数日志的优先级,下面进行分析,在console上我们通过cat /proc/sys/kernel/printk
文件来查看内核模块打印的优先级
# cat /proc/sys/kernel/printk
7 4 1 7
该文件里面有四个数值,这四个值是在kernel/printk.c
中被定义的,如下:
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 */
};
分别对应:
- 控制台日志级别:优先级高于该值的消息将被打印至控制台
- 默认的消息日志级别:将用该优先级来打印没有优先级的消息
- 最低的控制台日志级别:控制台日志级别可被设置的最小值(最高优先级)
- 默认的控制台日志级别:控制台日志级别的缺省值
在include/linux/printk.h
中内核一共定义了8个printk级别,数值越大优先级越低,如下:
#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 */
实际应用时:
- 我们会先把
DEFAULT_CONSOLE_LOGLEVEL
设置为8,这样优先级高于8的都会被打印到console(数值小于8);因为printk的最低级为7,则代表所有的log都会print到console上进行调试,待我们调试完成后,将DEFAULT_CONSOLE_LOGLEVEL
的值设置为低于我们要打印的级别,这样就不会有那么多没必要的log了。 - 可以通过echo的方式来直接修改log的优先级,如
echo 4 4 1 7 > /proc/sys/kernel/printk
- 当输入
printk("Hello, world!\n")
没有带任何优先级,则会采用默认级别,默认级别为4,和输入printk(KERN_WARNING"Hello, world!\n")
的效果是一致的。 - Debug信息设置为KERN_DEBUG,即
printk(KERN_DEBUG"Hello, world!\n")
,但我们观察到内核中都不会直接调用这个接口,而是重新提供了一个debug的接口函数,pr_debug(fmt, ...)
,这个将在下一部分进行讲解。
在cat /proc/sys/kernel/printk
文件的时候,发现该文件下面还有几个与printk相关的文件,如下:
cat /proc/sys/kernel/printk
7 4 1 7
cat /proc/sys/kernel/printk_delay
0
cat /proc/sys/kernel/printk_ratelimit
5
cat /proc/sys/kernel/printk_ratelimit_burst
10
这些文件分别表示:
-
printk_delay
中的值表示printk消息之间延迟的毫秒数,用于提高某些场景的可读写,如打印的太快了,我们也不可能从这种狂刷屏幕上读取到什么有效信息,所以减慢打印速度。 -
printk_ratelimit
和printk_ratelimit_burst
也有点这个调慢速度的作用,如上面的printk_ratelimit = 5,printk_ratelimit_burst = 10
,则表示当内核中由printk_ratelimit()
函数限制的打印信息每打印10次就会停止5s不再向console输出。
下面是一个测试的例子:
for (i = 0 ; i < 1000; i ++){
if(printk_ratelimit()){
printk(KERN_DEBUG "Test for ratelimte i = %d j = %d\n",i ,++j);
}
}
printk(KERN_NOTICE "After Test i = %d j = %d\n",i , j);
printk_ratelimit()
根据打印的频繁程度返回的一个值决定是否将debug信息打印出来。整个处理机制是,系统根据printk_ratelimit_burst
的值设置一个队列长度,如果这个队列满,则值printk_ratelimit()
为0,禁止新的消息加入队列,等待printk_ratelimit
秒设定的时间,将 printk_ratelimit()
设为1,即允许新的消息加入队列,进行再次打印。所以在上面的例子,我们看到输出为10次。
3.内核动态debug机制pr_debug函数的使用
pr_debug(fmt, ...)
函数的定义位于include/linux/printk.h中,如下:
/* If you are writing a driver, please use dev_dbg instead */
#if defined(DEBUG)
#define pr_debug(fmt, ...) \
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_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#endif
从上面可以看到pr_debug(fmt, ...)
函数一共会有三种方式:
- 如果定义了DEBUG,则使用
printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
,该函数即上面所说的方式。 - 如果没定义DEBUG而定义了
CONFIG_DYNAMIC_DEBUG
,则使用dynamic_pr_debug(fmt, ##__VA_ARGS__)
,该函数为内核动态debug机制。 - 如果都没定义,则使用
no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
,该函数会直接返回0。
在实际应用中我们都使用第二种方法,内核动态debug机制,这种方法可以按模块来确认是否打印该模块的调试信息,而第一种方式会将所有模块的debug信息都打印出来,我们可以做一个实验,在include/linux/printk.h
的最上面定义#define DEBUG,并把DEFAULT_CONSOLE_LOGLEVEL
设置为8,启动后我们会看到console上有成千上万的log,想找到有用的信息都难,这就是因为定义了DEBUG后内核中所有的模块debug都被开放了。
下面就说说怎样添加需要调试的模块添加动态debug机制,以打开char驱动的debug机制为例:
- 配置Kconfig,添加要调试驱动模块的DEBUG选项,在driver/char目录下的Kconfig中添加如下代码:
config OPEN_CHAR_DEBUG
- 配置Makefile,添加编译支持驱动模块
EXTRA_CFLAGS += -DDEBUG
在driver/char目录下的Makefile中添加如下代码:
- 在内核的.config文件中添加该模块的支持
CONFIG_LINYE_CHAR_DEBUG=y
,或者通过make configure来选中新增加的这个模块。
通过这三步设置我们就可以在driver/char下面使用pr_debug(fmt, ...)
函数了。
4.printf与printk函数的区别
在文章的开头已经有说道“内核驱动的调试过程我们一般会使用内核提供的printk函数来进行调试,在应用层时我们会使用标准的c库函数printf“所以它们之间最大的区别就是,在Linux内核是不支持printf函数,在应用层也是无法使用printk函数。
1.下面列举出一些区别
- printk()函数是直接使用了向终端设备写函数tty_write()。而printf()函数是调用write()系统调用函数向标准输出设备写。所以在用户态(如进程0)不能够直接使用printk()函数,而在内核态由于他已是特权级,所以无需系统调用来改变特权级,因而能够直接使用 printk()函数。
- printk可以以日志等级的形式进行打印信息。
- printk无法打印浮点型数据,printf可以打印浮点型数据。
- printk是“行驱动”的,说只有收到一个换行符数据才会真正输出到终端,否则就不会有任何信息输出。
2.几个常用的字符格式化函数
- sprintf
把格式化的字符串输出到指定字符串中(char buffer[50]),例:
sprintf( buffer,"String:%s", "abc");`则`buffer = "String:abc"
- vsprintf
把参数可变的字符串进行格式化后输出到指定字符串中,例:
void log(const char* format, ... )
{
char buf[50]
va_list args;
va_start (args, format);
vfprintf (buf, format, args);
va_end (args);
}
- fprintf
把格式化的字符串输出到指定文件设备中(FILE* stream),例:
void log(void)
{
FILE* stream;
stream = fopen("fprintf.out", "w");
fprintf(stream, "%s%d", "aa", 1);
fclose(stream);
}
- vfprintf
把参数可变的字符串进行格式化后输出到指定文件设备中,例:
void log(FILE *file, const char* format, ... )
{
va_list args;
va_start (args, format);
vfprintf (file, format, args);
va_end (args);
}
5.shell 中打印调试信息的方法
在写shell脚本的时候,有时也需要打印log到console上进行观察,下面列出几种方法:
1.echo
最直接的方式就是这节在需要打印的位置使用echo函数写数据到/dev/console进行显示,例:
echo "this is debug meg!" > /dev/console
num=1
echo $num > /dev/console
2.logger
logger其实使用的是系统日志模块syslog,这里面感觉内容比较多,后面单独做一个总结,这边先不过多介绍。
3.shell调试
shell也有一个真实的调试模式:
1、如果在脚本"test.sh" 中有错误,可以这样来进行调试:
sh -n test.sh,这将返回所有语法错误。
2、如果想看脚本"test.sh" 中所有变量的值,可以这样来进行调试:
sh -x test.sh,这将执行该脚本并显示所有变量的值,每5秒刷新一次。
3、sh -v test.sh,一边执行脚本,一边将执行过的脚本命令打印到标准错误输出,如果哪边出错则停止。
6.tips
1、如何在每条打印信息前添加时间参数
在.comfig里面添加CONFIG_PRINTK_TIME = y
2、通过dmesg可以查看log_buf内核环形缓存区的数据
Linux print system的分析就到这边,有感悟时会持续会更新。