【问题】
当然kernel版本是2.6.28.4,内核在启动时候,在自解压后,输出done, booting the kernel后,需要等待几秒才能看到kernel版本等信息Linux version 2.6.28.4的打印:
Starting kernel ...
Uncompressing Linux..................................................................... done, booting the kernel.
【此处需要等待好几秒】
Linux version 2.6.28.4-as353x-patch-svn1602-dirty () (gcc version 4.2.4) #161 Fri Mar 12 17:57:33 CST 2010
CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
CPU: VIVT data cache, VIVT instruction cache
Machine: as353x。。。。。。。。。。。。。
而相比之下,之前的2.6.22的版本的kernel,是不需要此等待时间,就可以很快接着往下执行代码,看到kernel的版本信息的。
【解决过程】
1.去找源码,在内核
arch/arm/boot/compressed/misc.c的
ulg
decompress_kernel(ulg output_start, ulg free_mem_ptr_p, ulg free_mem_ptr_end_p,
int arch_id)
{
output_data = (uch *)output_start; /* Points to kernel start */
free_mem_ptr = free_mem_ptr_p;
free_mem_end_ptr = free_mem_ptr_end_p;
__machine_arch_type = arch_id;
arch_decomp_setup();
makecrc();
putstr("Uncompressing Linux...");
gunzip();
putstr(" done, booting the kernel.\n");
return output_ptr;
}
,但是,没找到谁调用此函数的。后来去找到了,是在arch/arm/boot/compressed/head.S中调用的。
之后,就执行到init/main.c中start_kernel了。
2.进入start_kernel,添加打印,看看是否能够输出,实际是可以输出的,但是,不论在何处添加打印,包括此函数的第一行,其最后显示出来的,也还是在延迟了2,3秒后,才看到此输出信息。所以,认为发生延迟的部分,还是在此函数之前。
3.想到了,试试打印jiffies,然后计算出各个函数之间的差值,就可以知道哪个部分最耗时间了,但是实际执行结果,打印的jiffies,都是-3000或者-2980之类的值,说明此时jiffies还不可用。
4.最后,想到了,之前看到printk的机制,实际执行的过程,是在内核console初始化成功之后,才会把你之前printk打印的东西,当
时放在buffer里面,现在才会输出,所以,我们看到的输出的时候,已经早就过了前面的那些初始化部分了。所以,耗时的部分,在解压kernel到最后
成功打开console,中间都可能发生。
正确定位问题范围,就容易解决问题了。无意间,发现我们有个函数usbOtgIfIRQ,在开始的时候就输出了,想到,是否可能是,此usb初始化
的时候,很弱智的去delay了很长时间,然后去找了下代码发现,还真是的,usb驱动,是某人从我们的别的平台移植到此linux上的,结果其中的很多
延迟等代码,都没有正确的处理,导致其中保留了诸如mdelay(1000);这种代码,白白地在此等待了1秒,所以才让开始提到的问题,在done,
booting the kernel之后,要等待个2,3秒,才能出现kernel打印信息,
【解决办法】
去掉了那多余的等待(至少是不必等待如此长的时间)或者是缩短等待时间,比如mdelay(10)就足够了,这样就明显缩短了等待时间,减少了1秒左右。剩下还剩大概不到1秒,觉得属于正常情况了。
【总结】
首先要明确问题所涉及内容的内部机制,才可能有效地解决问题。
【后记】
上面那个,只是解决了部分问题,因为等待时间有2,3秒,上面那个只是去掉其中的1秒,其他的部分,是系统正常启动的整体时间,全部加起来,也应该很短,至少不会在done, booting the kernel之后,让你感觉到明显的停顿才对,因此,要继续调试。
1.加入printk的时间显示,找到最耗时的部分。
去kernel的menuconfig中,找到
Kernel hacking ---> [*] Show timing information on printks
这样就可以使得启动的打印输出中,加上时间戳了。
最后发现,是在DMAC驱动注册之后,和UART驱动初始化之前,这部分最耗时间:
。。。。
[42949373.510020] pl08xdmaapi dmacp: pl08x_probe - ARM(R) PL08X DMA driver found
[42949373.510020] current jiffies:0xffff8b07
[42949373.510020] pl08xdmaapi: probe of dmacv failed with error -1
[42949373.510020] current jiffies:0xffff8b07
[42949374.210021] Serial: AMBA PL011 UART driver
[42949374.210022] uart0: ttyAMA0 at MMIO 0xc80000 (irq = 59) is a AMBA/PL011
[42949374.220004] current jiffies:0xffff8b4e
[42949374.220004] uart1: ttyAMA1 at MMIO 0xc90000 (irq = 60) is a AMBA/PL011
。。。
中间时间差值大概有0.7秒左右,而正常的其他Linux内核初始化的函数,都是非常短,基本都是在微秒左右,而不应该这样长。
2.继续去调试,开始是怀疑DMAC的驱动有问题,所以去dmac的驱动中加printk打印,最后发现,虽然耗时部分,不是这里,然后继续加打印,去driver和bus注册匹配的相关函数,都去加了打印,结果根据printk的时间戳显示,消耗的时间都是正常的。
3.调试过程中通过dump_stack()得知函数调用关系,发现了__early_initcall_end函数,
找对应代码,找到了这里,init\main.c中:
static void __init do_initcalls(void)
{
initcall_t *call;
for (call = __early_initcall_end; call < __initcall_end; call++)
do_one_initcall(*call);
/* Make sure there is no pending stuff from the initcall sequence */
flush_scheduled_work();
}
其中,__early_initcall_end和__initcall_end,以及其中间的那些init类型的函数,都可以通过make内核产
生的system.map中找到,这里,找到了在DMAC驱动probe函数pl08x_init和UART对应的初始化函数pl011_init那些中
间的函数们:
。。。
c001d9f4 t __initcall_pl08x_init6
c001d9f8 t __initcall_rand_initialize6
c001d9fc t __initcall_tty_init6
c001da00 t __initcall_pty_init6
c001da04 t __initcall_sysrq_init6
c001da08 t __initcall_pl011_init6
。。。
也就是说,对于耗时的函数,就在上面那些rand_initialize,tty_init,pty_init,sysrq_init中间。
4.最后通过加打印,找到了最耗时的函数部分:
drivers\char\pty.c中
static int __init pty_init(void)
{
。。。
legacy_pty_init();
。。。
}
而上面的这个函数legacy_pty_init,是在定义了宏#ifdef CONFIG_LEGACY_PTYS的情况下,才会实现,
所以此处就是我们配置了#ifdef CONFIG_LEGACY_PTYS,而从此宏定义的意思看,就是属于旧的东西,所以去内核中确认了一下,对应的配置选项是
Device Drivers - > Character devices ---> Serial drivers ---> [ ] Legacy (BSD) PTY support
取消此选择,就可以了,再去验证一下,是否应该内核正常使用,经过验证,发现是可以不选的,内核是可以正常工作的。
【总结】
要熟悉内核初始化的流程,以及时刻想到system.map,会对解决这类问题,大有帮助。