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.      结论

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