linux的内核日志系统

　　今天有同事问我在应用程序中怎么打印信息，在内核中有printk，用户空间用什么？我感到这个问题很奇怪，用printf不就可以了吗？他说他的 代码在一个so中，我都无语了！他原来是做windows的，在windows中很多都是win32程序，带界面的，不是控制台程序，他大多数通过单步跟 踪和断点来了解程序运行时的信息，其实吧，我倒是挺不喜欢单步或者断点的，除了特殊的调试需要，一般我都是通过打印日志来获取信息，linux有强大的日 志记录系统，可以给程序一个安心的多的执行环境，日志仅仅是一个旁路的作用，起到记录个审计的作用而不会影响程序的执行，单步和断点就不同了，很多的问题 你仅仅通过单步是无法发现的，特别是并发问题，不过在windows上写代码的哥们总是喜欢单步，就像他们总喜欢反汇编一样，这里面的原因就是，第 一，windows程序大多数不是控制台，它实际上没有地方打印信息，第二，windows拥有强大的可视化IDE，这就给单步和断点提供了方便。

　　在linux中，syslogd是用户空间的一个守护进程，所有的需要记录日志的别的进程可以和这个守护进程通信，可以委托这个守护进程帮助记录日 志，为何不自己记录呢，那是因为syslogd非常的专业，可以将日志记录到很细的地步，可以看etc/下面的配置文件，既然所有的进程都可以委托 syslogd记录日志，那么就涉及到了进程间通信，这就是linux中另外一大块的内容了，这里就不谈了，linux善于使用小的程序组合成大的机 制，linux善于分布式的思想而不是集中的，但是为何将日志都委托给一个守护进程呢，这不就集中了吗？其实这难道不是各司其职吗？因此这还是一个边界的 问题。syslogd之外还有一个klogd，这两个其实不是一个层次的，syslogd是个总的日志记录器，而klogd仅仅是一个syslogd的客 户端罢了，和很多需要记录日志的进程的级别一样，在需要记录日志的进程里，可以调用syslog函数将日志发送给syslogd守护进程，可是内核并不是 一个进程，那么它的日志就有必要专门设置一个用户进程负责传给syslogd，这个进程就是klogd，至于klogd如何从内核得到内核日志信息，这就 是它自己的事情了，其实内核专门留下了两个日志接口，一个是sys_syslog系统调用（注意不要和syslog函数混淆，syslog系统调用是和内 核通信的，而syslog函数是和syslogd通信的），另一个是/proc/kmsg文件，klogd使用的是后者，当然也可以直接使用 ksyslog系统调用。这里首先看一下内核日志的一些结构，首先内核日志大多数由printk产生，你也可以认为完全由printk产生，但是我们知 道，printk将信息打印到了屏幕，并没有别的什么副作用，实际上并不是仅仅发生了我们看到的事情，实际上printk并不是将信息直接写入了标准输出 文件，而仅仅将信息塞入了一个环形缓冲区，，然后至于这个缓冲区的内容什么时候显示到标准输出，那就是另外一个事情了，而内核日志就是存在于这个环形缓冲 区，打印到屏幕的仅仅是一个缓冲区副本，真正的数据还在缓冲区保留，只有到了klogd或者别的什么调用syslog系统调用将信息读出时或者缓冲区满了 （环形缓冲区首尾相接）的时候才会清除部分数据或者全部数据，刚才说了有两种方式来得到内核日志，一个是/proc/kmsg。一个是系统调用，幸运的 是，这两个都是调用了do_syslog内核函数：

　　int do_syslog(int type, char __user * buf, int len)

　　{

　　unsigned long i, j, limit, count;

　　int do_clear = 0;

　　char c;

　　int error = 0;

　　error = security_syslog(type);

　　if (error)

　　return error;

　　switch (type) {

　　...

　　case 2:

　　...

　　error = wait_event_interruptible(log_wait, (log_start - log_end)); //如果没有数据，那么就睡眠等待。

　　if (error)

　　goto out;

　　i = 0;

　　spin_lock_irq(&logbuf_lock); //如果要往外读数据，不希望在读的过程中数据发生变化，因此必须锁住环形数据缓冲区

　　while (!error && (log_start != log_end) && i

　　c = LOG_BUF(log_start); //得到一个字符

　　log_start++; //只有在这里才逻辑上清除环形缓冲区的数据

　　spin_unlock_irq(&logbuf_lock);

　　error = __put_user(c,buf);

　　buf++;

　　i++;

　　spin_lock_irq(&logbuf_lock);

　　}

　　spin_unlock_irq(&logbuf_lock);

　　...

　　}

　　我们看一下printk调用的vprintk内核函数：

　　asmlinkage int vprintk(const char *fmt, va_list args)

　　{

　　unsigned long flags;

　　int printed_len;

　　char *p;

　　static char printk_buf[1024];

　　static int log_level_unknown = 1;

　　...

　　spin_lock_irqsave(&logbuf_lock, flags); //这个logbuf_lock自旋锁其实很重要，确保一次内核信息写的过程不会有别的写过程来捣乱，否则很多信息会揉在一起，比如hello和 world会变为hwellorold。

　　printed_len = vscnprintf(printk_buf, sizeof(printk_buf), fmt, args);

　　for (p = printk_buf; *p; p++) {

　　if (log_level_unknown) {

　　if (p[0] != '<' || p[1] <'' || p[1] > '7' || p[2] != '>') {

　　emit_log_char('<');

　　emit_log_char(default_message_loglevel + '');

　　emit_log_char('>');

　　}

　　log_level_unknown = 0;

　　}

　　emit_log_char(*p);

　　if (*p == ' ')

　　log_level_unknown = 1;

　　}

　　if (!cpu_online(smp_processor_id()) && system_state != SYSTEM_RUNNING) {

　　spin_unlock_irqrestore(&logbuf_lock, flags);

　　goto out;

　　}

　　if (!down_trylock(&console_sem)) { //如果现在可以得到设备的信号量，那么马上将数据显示到终端

　　console_locked = 1;

　　spin_unlock_irqrestore(&logbuf_lock, flags);

　　console_may_schedule = 0;

　　release_console_sem(); //该函数具体显示数据

　　} else {

　　spin_unlock_irqrestore(&logbuf_lock, flags);//本次的内核信息已经写入了内核环形缓冲，为了不阻碍别人写，释放掉自旋锁

　　}

　　out:

　　return printed_len;

　　}

　　内核的环形缓冲有两个用途，一个是直接打印在屏幕上，还有一个就是可能用户空间的内核日志程序正在运行，因此这个函数完成了两个作用：

　　void release_console_sem(void)

　　{

　　unsigned long flags;

　　unsigned long _con_start, _log_end;

　　unsigned long wake_klogd = 0;

　　for ( ; ; ) { //打印向屏幕，注意，打印的时候也要确保logbuf_lock被拥有，因为不想在打印过程中发生缓冲区变化的事情

　　spin_lock_irqsave(&logbuf_lock, flags);

　　wake_klogd |= log_start - log_end; //确保有数据，这个变量还作为是否唤醒do_syslog的睡眠队列的依据。

　　if (con_start == log_end)

　　break; /* Nothing to print */

　　_con_start = con_start;

　　_log_end = log_end;

　　con_start = log_end; //注意，log_end和log_start并没有变化，而是副本变化了，这是因为下面还要用到内核缓冲，不能因为写到了屏幕，信息就消耗了。

　　spin_unlock_irqrestore(&logbuf_lock, flags);

　　call_console_drivers(_con_start, _log_end);

　　}

　　console_locked = 0;

　　console_may_schedule = 0;

　　up(&console_sem);

　　spin_unlock_irqrestore(&logbuf_lock, flags);

　　if (wake_klogd && !oops_in_progress && waitqueue_active(&log_wait)) //如果内核唤醒缓冲中有数据，那么就唤醒睡眠队列

　　wake_up_interruptible(&log_wait);

　　}

　　最后我们看一下procfs导出的kmsg接口的read函数，其实也是调用了do_syslog函数：

　　static ssize_t kmsg_read(struct file *file, char __user *buf, size_t count, loff_t *ppos)

　　{

　　if ((file->f_flags & O_NONBLOCK) && !do_syslog(9, NULL, 0))

　　return -EAGAIN;

　　return do_syslog(2, buf, count);

　　}

　　这里我觉得有一个问题，就是在printk的时候，如果我们恰好可以得到设备的信号量，那么就必须等到信息完全显示到设备上时调用栈才可以返回，也 就是说，最好不要在内核大量调用printk函数，另外，在多处理器上这也是很不利的，以前的处理器少，因此问题不大，现在都是多处理器了，性能就可能受 printk的影响了，我觉得可以为每一个cpu准备一个环形缓冲区，然后在拼接这些缓冲区的时候进行控制，比如在用户空间读每个cpu的缓冲区，只不过 将它们作为一个整体去理解，这个我感觉可以用文件系统实现。在任何程序中频繁调用打印都是不妙的，因为打印涉及设备操作，想想看，外设相比cpu多么慢， 而且对于机器中的唯一设备，而且是每个进程几乎都在用的设备，我们花在打架上的时间又是何等的长。

　　回归同事问我的那个问题，在linux上怎么打印信息，其实，只要你不关闭，每个程序都会默认打开0，1，2三个文件描述符，这三个描述符在start_kernel中调用的kernel_init进程（最终成为/sbin/init）中被初始化，也就是在下面的代码：

　　if (sys_open((const char __user *) "/dev/console", O_RDWR, 0) <0)

　　printk(KERN_WARNING "Warning: unable to open an initial console. ");

　　(void) sys_dup(0);

　　(void) sys_dup(0);

　　在这里，sys_open打开了/dev/console，将其作为标准输出，其实也就是我们的终端，当前终端，在sys_open中会自动将文件 描述符0分配给这个终端文件，然后紧接着的sys_dup相当于复制了这个终端文件描述符代表的文件给了新的描述符1和2，这样的话实际上0，1，2代表 的是同一个东西，都是指当前的终端，这也就是为什么你往标准错误里面写东西也不会错的道理，实际上标准输入，输出，错误都是给用户进程用的，对于内核，它 们是一个东西。因为linux进程都是fork出来的，根源就是这个kernel_init进程，于是每个进程都会默认复制父进程的0，1，2文件描述符 （如果父进程没有关闭它们的话）。