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的分析就到这边，有感悟时会持续会更新。
