Printk与sched_clock_init的一点分析

在分析Linu内核启动的过程中，发现一段“不平常”的日志，感觉产生这段日志的代码肯定是“不可思议”的。因此就大致分析了一下：

日志如下：

[ 0.000000] console [ttyMT0] enabled

[ 2.157770] Calibrating delay loop... 1694.10 BogoMIPS (lpj=4235264)

更精细的日志如下：

        [    0.000000] start:sched_clock_init.

        [    2.100505] end  :sched_clock_init.

与这段日志有关的代码是：

void sched_clock_init(void)

{

    /*printk(KERN_CRIT “start:sched_clock_init.\n”)*/

    sched_clock_running = 1;

    /*printk(KERN_CRIT “end  :sched_clock_init.\n”)*/

}

难道这一句简简单单的赋值就会花费两秒是的时间？？那么就分析一下相关的代码：sched_clock_running作用和printk的实现。

 

1.      sched_clock_running的作用

分析发现，调用sched_clock_running的地方仅仅有函数sched_clock_cpu():

u64 sched_clock_cpu(int cpu)

{

    if (unlikely(!sched_clock_running))

       return 0;

 

    return sched_clock();

}

很明显，如果sched_clock_running为0(unlikely已经说明sched_clock_running很少为0)，则返回0；如果不为0，调用sched_clock返回当前的调度时钟时间(相对系统起始的时间，单位为纳秒)。

函数sched_clock_cpu()被大约四个函数调用cpu_clock() / local_clock / update_rq_clock() / ttwu_queue()。

 

综上可知，执行sched_clock_init之前，获取的调度时钟时间都是0，执行sched_clock_init之后，取得的调度时钟时间都是有非零值的。

 

2.      Printk()的实现

Printk的实现都在文件./kernel/printk.c中。Printk() ->  vprintk()，而在vprintk()会通过cpu_clock()获取时间。而有上可知，能否打印时间是和sched_clock_init有没有被执行是有直接关系的。

 

3.      结论

通过分析，可以知道，日志中显示的两秒的差距不是因为执行语句花费了两秒，而是因为在该语句之前，没有获取到有效的调度时钟时间。