Linux print system

作者: Creator_Ly | 来源:发表于2017-01-03 09:45 被阅读470次

题图：nipic

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
. bool "Support OPEN CHAR DEBUG"
. depends on ARM
. help
. this is DEBUG function

配置Makefile，添加编译支持驱动模块 EXTRA_CFLAGS += -DDEBUG
在driver/char目录下的Makefile中添加如下代码：

. ifeq($(CONFIG_OPEN_CHAR_DEBUG), y)
. EXTRA_CFLAGS += ‐DDEBUG
. endif

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

注：以上内容都是本人在学习过程积累的一些心得，难免会有参考到其他文章的一些知识，如有侵权，请及时通知我，我将及时删除或标注内容出处，如有错误之处也请指出，进行探讨学习。文章只是起一个引导作用，详细的数据解析内容还请查看Linux相关教程，感谢您的查阅。

Linux print system

Linux print system

1.内核printk函数工作原理

2.内核printk函数打印优先级

3.内核动态debug机制pr_debug函数的使用

4.printf与printk函数的区别

5.shell 中打印调试信息的方法

6.tips

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

我用 Linux

程序员

工具癖

开源工具技巧