printk 工作原理

printk()的参数个数是可变的，linux内核中提供了va_arg机制。该机制主要通过3个宏来实现： 
    va_arg(ap, T)：获取ap中的一个参数，该参数的类型是T，然后ap自加sizeof(T)，跳过刚获取的参数。 
    va_end(ap)：该宏定义为空。 
    va_start(ap, A)：通过A获取参数列表的地址，A是printk的第一个参数（fmt）。一个函数的参数，是按从右到左的顺序逐个入栈的，因此通过A的地址加上A的大小(通常为4Bytes),就可以获得从第二个参数开始的参数列表的首地址。 
    printk()函数首先使用va_start(args, fmt)，将第二个参数的地址存入args变量。然后调用vprintk(fmt, args)，vprintk完成具体的输出任务，返回值为输出的字符的个数。 
    下面我们详细讨论vprintk的实现。 
    printk机制中有两个主要的缓存：一个是printk_buf,一个是log_buf。前者用来存储将要输出的字符串，fmt+报错信息（如果有的话）。后者用来存储最终要输出的字符串，是整个printk机制的核心。log_buf是一个环形数组，默认大小为128K。配合这个缓冲使用的有3个变量： 
    static unsigned log_start;      /* Index into log_buf: next char to be read by syslog() */ 
    static unsigned con_start;      /* Index into log_buf: next char to be sent to consoles */ 
    static unsigned log_end;        /* Index into log_buf: most-recently-written-char + 1 */ 
    在用到这个缓冲时，我们再详细的介绍。 
    vprintk首先会调用函数boot_delay_msec()，进行忙等待一段时间。这段时间的大小是由内核启动参数boot_delay指定的。boot_delay的单位是毫秒。不知道这里为什么要等待。 
    然后调用preempt_disable()禁止抢占机制。接下来是关中断，获取当前CPU的编号。 
    如果在某个CPU上正在执行printk时，突然崩溃掉，........ 
    vscnprintf()函数，将输出的字符串按fmt中的格式编排好，放入printk_buf中，并返回应该输出的字符的个数。为了保证完整性，我们还是来谈谈vscnprintf()函数的实现吧。 
    vscnprintf()调用的是vsnprintf(buf,size,fmt,args)。该函数进行主要的格式化操作。其首先判断size是否小于0，若小于0，则给出一个警告，并返回0。然后对格式化字符串fmt进行遍历，如果fmt当前的字符不是"%",直接将其考入buf中，若是"%"，则后面的处理要复杂一点。相信读者对printf和printk的使用方法都很熟悉，"%"后面一般会跟一个标志符，这种标志符共有5个，'-','+','#','SPACE','0'。标志符'-'表示后面的字符靠左输出，比如printk("%-10c",'a'),会先输出'a',再输出9个空格。'#'标志的作用是当后面输出16进制的数据时，会自动在数据前加上"0x",比如printk("%#x",10),会输出"0xa"。'+'标志的作用是在输出的数字前自动加上一个"+",比如printk("%+d/n",10),输出结果为:"+10"。这里会根据不同的标志符对一个标志变量"flags"进行置位。各标志符对应的bit如下： 
    #define ZEROPAD 1               /* pad with zero -- '0'*/ 
    #define SIGN    2               /* unsigned/signed long --  */ 
    #define PLUS    4               /* show plus -- '+' */ 
    #define SPACE   8               /* space if plus -- ' ' */ 
    #define LEFT    16              /* left justified -- '-' */ 
    #define SMALL   32              /* Must be 32 == 0x20 */ 
    #define SPECIAL 64              /* 0x -- '#' */ 
    在标志符的后面通常是输出宽度，这是一个数字，vsnprintf()定义了一个变量来获取这个值，首先，我们需要判断紧接着标志符后面的是不是数字，如果是则通过skip_atoi()将该数字字符串转化成数字。skip_atoi()的实现很简洁： 
    static int skip_atoi(const char **s) 
    {//change the string "s" to digit 
            int i=0; 
 
            while (isdigit(**s)) 
                    i = i*10 + *((*s)++) - '0'; 
            return i; 
    } 
    对于内核中的这类函数最好能记熟一点，在用的时候就不用再费时间自己实现了。在这里有一点需要强调的是"%*"，至少我以前并不知道"%*"的含义，"*"对应后面的一个参数，这个参数指定输出的宽度。比如:printk("%*c",10,'a');会先输出9个空格再输出字符'a'。你甚至可以给一个负值，表示靠左输出。获取的输出宽度保存在变量field_width中。 
    接下来处理的是输出精度，在格式化输出浮点数时，我们经常采用".num"的形式来指定小数点后输出几位有效数字。在处理的时候，首先判度当前字符是不是'.'，如果是，那么读入后面紧跟着的数字，保存在变量precision中。这里也可以使用".*"的形式，将精度放到后面的参数中指定。 
    接着是读取限定符，如果有的话。什么是限定符呢? 如果我们想输出一个长整数，会用到"%ld",这里的"l"便是限定符，用于辅助说明输出数据的具体类型。printf或printk中用的限定符有:"h,l,L,Z,z,t"。另外"ll"相当于"L"。大家应该能猜到下一步应该做什么了，没错，判断输出数据的类型。可能的类型有"c,s,p,n,%,o,X,x,d,i,u"，这里的实现都很简单，如果大家有兴趣，可以自己去看源代码。 
    有一个问题到现在一直没有说明，就是如何从参数列表中获得想要的参数。其实在文章刚开始的时候提到了一点，就是va_arg()宏，该宏每次根据指定的类型读取一个参数，然后将参数列表的开始位置自动向前移一个。这样，我们在分析"fmt"的格式的同时也就把对应的参数放到了输出字符串(printk_buf)中合适的位置上。 
    分析完"fmt"后，函数vsnprintf()返回应该输出的字符个数。 
    执行流有返回到了函数vprintk()中，我们接着来看。下面是一个for循环，用于将printk_buf中的输出字符串拷贝到日志缓存log_buf中。首先需要判度输出的级别，我们知道在printk中，可以指定8个输出级别，通过printk("<x>...")来指定。这里的输出级别被保存到变量current_log_level中。 
    下面用到了一个函数emit_log_char(): 
    static void emit_log_char(char c) 
    {// write c into log. the log buf is ring queue, the defaut is 128K. 
            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++; 
    } 
    这个函数的作用是把字符c写道日志缓存log_buf中，并更新log_start，log_end，con_start的值。 
    接下来有个需要解释一下的问题，就是printk_time。我们在启动内核的时候可以通过指定一个内核启动参数"time",来使所有printk出来的数据前加入当前时间。这个时间是从系统启动到这个printk时所逝去的时间。 
                        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);//the unit of t is 
nanosecond 
                                nanosec_rem = do_div(t, 1000000000);//Now, the 
unit of t is second, the unit of nanosec_rem is nanosecond. 
                                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; 
                        } 
    函数cpu_clock()返回从系统启动到当前的纳秒值。do_div(a,b)是一个宏，它计算a/b,将商放在a中，返回余数。那么tbuf中的数据便是"[second.nanosecond]"形式的。有兴趣的话，大家可以在内核启动时加入time参数试一试，看看会有什么效果。 
    在for循环结束后，printk_buf中的数据便按照新的输出格式(比如在每一行前面加入print_time)copy到了log_buf中。 
    下面便是具体的输出工作了，在输出之前，需要先获取信号量console_sem，这里获取的方式采用的是down_trylock(&console_sem)。这个函数在没有获取信号量时不会睡眠，而是立即返回一个非0值。另外，我们还需要释放锁console_locked和logbuf_lock。这些工作在函数acquire_console_semaphore_for_printk(this_cpu)中完成，当该函数成功返回时，会调用函数release_console_sem()进行显示工作。这个函数会再调用call_console_drivers(_con_start, _log_end)将_con_start，_log_end之间的log_buf中的内容。函数call_console_drivers()首先判断输出级别，然后根据输出内容，按行调用函数_call_console_drivers(start_print, cur_index, msg_level)，该函数的作用是处理环形队列，将正确的内容作为参数调用函数__call_console_drivers(start, end)，该将输出内容发送给console的驱动。在内核中，所有的console都被链入了一个链表--console_drivers，在这里，我们要遍历这个链表，如果某个console允许输出的话，就调用它的write()方法。 
/* 
 * Call the console drivers on a range of log_buf 
 */ 
static void __call_console_drivers(unsigned start, unsigned end) 
{ 
        struct console *con; 
 
        for (con = console_drivers; con; con = con->next) {//All consoles belongs to a list -- console_drivers. 
                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的过程就结束了。哦，不！还有一个工作没有做，就是将输出内容同时写入日志。这个工作是由内核中的守护进程klogd来完成的。在函数release_console_sem(void)的最后，会判断是否需要唤醒klogd，然后调用wake_up_klogd()来唤醒守护进程。那么什么时候需要唤醒klogd呢?只要log_buf中有未输出的信息，便需唤醒klogd将其写入日志文件。 

    OK!现在是真的结束了。如果有什么问题，可以跟我联系，共同讨论。 

内核通过 printk() 输出的信息具有日志级别，日志级别是通过在 printk() 输出的字符串前加一个带尖括号的整数来控制的，如 printk("<6>Hello, world!/n");。内核中共提供了八种不同的日志级别，在 linux/kernel.h 中有相应的宏对应。

#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 */
#define KERN_INFO     "<6>"    /* informational */
#define KERN_DEBUG    "<7>"    /* debug-level messages */

所以 printk() 可以这样用：printk(KERN_INFO "Hello, world!/n");。

未指定日志级别的 printk() 采用的默认级别是 DEFAULT_MESSAGE_LOGLEVEL，这个宏在 kernel/printk.c 中被定义为整数 4，即对应KERN_WARNING。

在 /proc/sys/kernel/printk 会显示4个数值（可由 echo 修改），分别表示当前控制台日志级别、未明确指定日志级别的默认消息日志级别、最小（最高）允许设置的控制台日志级别、引导时默认的日志级别。当 printk() 中的消息日志级别小于当前控制台日志级别时，printk 的信息（要有/n符）就会在控制台上显示。但无论当前控制台日志级别是何值，通过 /proc/kmsg （或使用dmesg）总能查看。另外如果配置好并运行了 syslogd 或 klogd，没有在控制台上显示的 printk 的信息也会追加到 /var/log/messages.log 中。

char myname[] = "chinacodec/n";
printk(KERN_INFO "Hello, world %s!/n", myname);