在分析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. ”)*/
sched_clock_running = 1;
/*printk(KERN_CRIT “end :sched_clock_init. ”)*/
}
难道这一句简简单单的赋值就会花费两秒是的时间??那么就分析一下相关的代码: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. 结论
通过分析,可以知道,日志中显示的两秒的差距不是因为执行语句花费了两秒,而是因为在该语句之前,没有获取到有效的调度时钟时间。