2-Linux print system

题图: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_startva_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_buflog_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_startlog_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_ratelimitprintk_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相关教程,感谢您的查阅。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 151,688评论 1 330
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 64,559评论 1 273
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 101,749评论 0 226
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 42,581评论 0 191
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 50,741评论 3 271
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 39,684评论 1 192
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,122评论 2 292
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 29,847评论 0 182
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 33,441评论 0 228
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 29,939评论 2 232
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,333评论 1 242
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 27,783评论 2 236
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,275评论 3 220
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,830评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,444评论 0 180
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 34,553评论 2 249
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 34,618评论 2 249

推荐阅读更多精彩内容