Kernel Start-up Time

Kernel Start-up Time

[Caglar Akyuz]

Hello,

While measuring Linux start-up time, I see that printing version string in 
"start_kernel" takes ~1.3 seconds. I guess this is the time between from 
"bootloader jumping to uImage" and "printing version string in generic 
start_kernel code". Relevant part of my boot log is attached.

My question: is it normal this 1.3 sec init time? My system is 297 MHZ 
arm926ej-s with a 162MHZ DDR2 memory.

Sorry for my ignorance but I'm not good at ARM assembly, so I'm unable to 
bench early boot.

Thanks,
Caglar

_____________________________________________________________________ 

[    4.390970] Bytes transferred = 3349376 (331b80 hex)                                                                                                                             
[    4.663038] ## Booting kernel from Legacy Image at 80700000 ...                                                                                                                  
[    4.668940]    Image Name:   Linux-2.6.30-davinci1-06079-g4e7                                                                                                                    
[    4.672999]    Image Type:   ARM Linux Kernel Image (uncompressed)                                                                                                               
[    4.677999]    Data Size:    3349312 Bytes =  3.2 MB                                                                                                                             
[    4.681965]    Load Address: 80008000                                                                                                                                            
[    4.684007]    Entry Point:  80008000                                                                                                                                            
[    4.686043]    Loading Kernel Image ... OK                                                                                                                                       
[    4.696911] OK                                                                                                                                                                   
[    4.700878]                                                                                                                                                                      
[    4.700896] Starting kernel ...                                                                                                                                                  
[    4.702971]                                                                                                                                                                      
[    5.966039] [    0.000000] Linux version 2.6.30-davinci1-06079-g4e73fae-
dirty (caglar at ycaserv) (gcc version 4.3.3 (GCC) ) #393 PREEMPT Mon Jan 18 
10:03:47 EET 2010              
[    5.979054] [    0.000000] CPU: ARM926EJ-S [41069265] revision 5 
(ARMv5TEJ), cr=00053177                                                                                         
[    5.985952] [    0.000000] CPU: VIVT data cache, VIVT instruction cache

Kernel Start-up Time

[Tonyliu]

Caglar Akyuz wrote:
> Hello,
>
> While measuring Linux start-up time, I see that printing version string in 
> "start_kernel" takes ~1.3 seconds. I guess this is the time between from 
> "bootloader jumping to uImage" and "printing version string in generic 
> start_kernel code". Relevant part of my boot log is attached.
>   
> My question: is it normal this 1.3 sec init time? My system is 297 MHZ 
> arm926ej-s with a 162MHZ DDR2 memory.
>   

It depends on where you start to measure it?
    Starting from when power is turned on.
    Starting from when the first instruction executes.
    Start from the bootloader tries to load the kernel image.
...
I think this type of mearsurement  makes no much sense to you, since 
normally
people want to know
   When the kernel loads userspace or
    When the first app starts to run.

These are more meaningful for specific product.

Tony

> Sorry for my ignorance but I'm not good at ARM assembly, so I'm unable to 
> bench early boot.
>
> Thanks,
> Caglar
>
> _____________________________________________________________________ 
>
> [    4.390970] Bytes transferred = 3349376 (331b80 hex)                                                                                                                             
> [    4.663038] ## Booting kernel from Legacy Image at 80700000 ...                                                                                                                  
> [    4.668940]    Image Name:   Linux-2.6.30-davinci1-06079-g4e7                                                                                                                    
> [    4.672999]    Image Type:   ARM Linux Kernel Image (uncompressed)                                                                                                               
> [    4.677999]    Data Size:    3349312 Bytes =  3.2 MB                                                                                                                             
> [    4.681965]    Load Address: 80008000                                                                                                                                            
> [    4.684007]    Entry Point:  80008000                                                                                                                                            
> [    4.686043]    Loading Kernel Image ... OK                                                                                                                                       
> [    4.696911] OK                                                                                                                                                                   
> [    4.700878]                                                                                                                                                                      
> [    4.700896] Starting kernel ...                                                                                                                                                  
> [    4.702971]                                                                                                                                                                      
> [    5.966039] [    0.000000] Linux version 2.6.30-davinci1-06079-g4e73fae-
> dirty (caglar at ycaserv) (gcc version 4.3.3 (GCC) ) #393 PREEMPT Mon Jan 18 
> 10:03:47 EET 2010              
> [    5.979054] [    0.000000] CPU: ARM926EJ-S [41069265] revision 5 
> (ARMv5TEJ), cr=00053177                                                                                         
> [    5.985952] [    0.000000] CPU: VIVT data cache, VIVT instruction cache
>
> _______________________________________________
> linux-arm-kernel mailing list
> linux-arm-kernel at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-arm-kernel
>
>   


-- 
Tony Liu | Liu Bo
-------------------------------------------------------------
WIND RIVER | China Development Center
Tel: 86-10-8477-8542 ext: 8542 |  Fax: 86-10-64790367
(M): 86-136-7117-3612
Address: 15/F, Wangjing TowerB, Chaoyang District, Beijing, P.R.China

Kernel Start-up Time

[Caglar Akyuz]

On Monday 18 January 2010 10:39:27 am Tonyliu wrote:
> Caglar Akyuz wrote:
> > Hello,
> >
> > While measuring Linux start-up time, I see that printing version string
> > in "start_kernel" takes ~1.3 seconds. I guess this is the time between
> > from "bootloader jumping to uImage" and "printing version string in
> > generic start_kernel code". Relevant part of my boot log is attached.
> >
> > My question: is it normal this 1.3 sec init time? My system is 297 MHZ
> > arm926ej-s with a 162MHZ DDR2 memory.
> 
> It depends on where you start to measure it?
>     Starting from when power is turned on.
>     Starting from when the first instruction executes.
>     Start from the bootloader tries to load the kernel image.
> ...

That number is relative, it is the time passing from u-boot jumping to kernel 
and kernel starting.

> I think this type of mearsurement  makes no much sense to you, since
> normally
> people want to know
>    When the kernel loads userspace or
>     When the first app starts to run.
> 

First application starts in ~4 second. This time consists of:

1) ~1 sec for application start.
2) ~1 sec for userspace init, mouting filesys, etc.
3) ~1 sec for kernel init for drivers and machine specific code
4) ~1 sec for the aforementioned delay.
 
> These are more meaningful for specific product.
> 

It is number 4 that I'm trying to understand. I think it has the highest 
chance to contribute to end goal. But if it is as expected, then no room for 
optimization there.

Regards,
Caglar

Kernel Start-up Time

[Steve Chen]

On Mon, 2010-01-18 at 10:54 +0200, Caglar Akyuz wrote:
> On Monday 18 January 2010 10:39:27 am Tonyliu wrote:
> > Caglar Akyuz wrote:
> > > Hello,
> > >
> > > While measuring Linux start-up time, I see that printing version string
> > > in "start_kernel" takes ~1.3 seconds. I guess this is the time between
> > > from "bootloader jumping to uImage" and "printing version string in
> > > generic start_kernel code". Relevant part of my boot log is attached.
> > >
> > > My question: is it normal this 1.3 sec init time? My system is 297 MHZ
> > > arm926ej-s with a 162MHZ DDR2 memory.
> > 
> > It depends on where you start to measure it?
> >     Starting from when power is turned on.
> >     Starting from when the first instruction executes.
> >     Start from the bootloader tries to load the kernel image.
> > ...
> 
> That number is relative, it is the time passing from u-boot jumping to kernel 
> and kernel starting.
> 
> > I think this type of mearsurement  makes no much sense to you, since
> > normally
> > people want to know
> >    When the kernel loads userspace or
> >     When the first app starts to run.
> > 
> 
> First application starts in ~4 second. This time consists of:
> 
> 1) ~1 sec for application start.
> 2) ~1 sec for userspace init, mouting filesys, etc.
> 3) ~1 sec for kernel init for drivers and machine specific code
> 4) ~1 sec for the aforementioned delay.
>  
> > These are more meaningful for specific product.
> > 
> 
> It is number 4 that I'm trying to understand. I think it has the highest 
> chance to contribute to end goal. But if it is as expected, then no room for 
> optimization there.
> 

Well, "no room for optimization" is a pretty strong statement.  Last
year Monta Vista demo the 1 second boot.

http://mvista.com/press_release_detail.php?fid=news/2009/Ultra-fast-boot.html&d=

I realized that it is a different and faster processor, but I'm pretty
sure there are plenty of places you can trim the boot time.   It is a
matter of time and effort.  You may want to start with the system
requirement to see if 4 seconds is good enough and go from there.

Regards,

Steve

Kernel Start-up Time

[Dirk Behme]

On 18.01.2010 16:39, Steve Chen wrote:
> On Mon, 2010-01-18 at 10:54 +0200, Caglar Akyuz wrote:
>> On Monday 18 January 2010 10:39:27 am Tonyliu wrote:
>>> Caglar Akyuz wrote:
>>>> Hello,
>>>>
>>>> While measuring Linux start-up time, I see that printing version string
>>>> in "start_kernel" takes ~1.3 seconds. I guess this is the time between
>>>> from "bootloader jumping to uImage" and "printing version string in
>>>> generic start_kernel code". Relevant part of my boot log is attached.
>>>>
>>>> My question: is it normal this 1.3 sec init time? My system is 297 MHZ
>>>> arm926ej-s with a 162MHZ DDR2 memory.
>>>
>>> It depends on where you start to measure it?
>>>      Starting from when power is turned on.
>>>      Starting from when the first instruction executes.
>>>      Start from the bootloader tries to load the kernel image.
>>> ...
>>
>> That number is relative, it is the time passing from u-boot jumping to kernel
>> and kernel starting.
>>
>>> I think this type of mearsurement  makes no much sense to you, since
>>> normally
>>> people want to know
>>>     When the kernel loads userspace or
>>>      When the first app starts to run.
>>>
>>
>> First application starts in ~4 second. This time consists of:
>>
>> 1) ~1 sec for application start.
>> 2) ~1 sec for userspace init, mouting filesys, etc.
>> 3) ~1 sec for kernel init for drivers and machine specific code
>> 4) ~1 sec for the aforementioned delay.
>>
>>> These are more meaningful for specific product.
>>>
>>
>> It is number 4 that I'm trying to understand. I think it has the highest
>> chance to contribute to end goal. But if it is as expected, then no room for
>> optimization there.
>>
>
> Well, "no room for optimization" is a pretty strong statement.  Last
> year Monta Vista demo the 1 second boot.
>
> http://mvista.com/press_release_detail.php?fid=news/2009/Ultra-fast-boot.html&d=
>
> I realized that it is a different and faster processor, but I'm pretty
> sure there are plenty of places you can trim the boot time.   It is a
> matter of time and effort.

Maybe

http://elinux.org/Boot_Time

could help you a little.

Best regards

Dirk

Kernel Start-up Time

[Caglar Akyuz]

On Monday 18 January 2010 05:39:03 pm Steve Chen wrote:
> On Mon, 2010-01-18 at 10:54 +0200, Caglar Akyuz wrote:
> > On Monday 18 January 2010 10:39:27 am Tonyliu wrote:
> > > Caglar Akyuz wrote:
> > > > Hello,
> > > >
> > > > While measuring Linux start-up time, I see that printing version
> > > > string in "start_kernel" takes ~1.3 seconds. I guess this is the time
> > > > between from "bootloader jumping to uImage" and "printing version
> > > > string in generic start_kernel code". Relevant part of my boot log is
> > > > attached.
> > > >
> > > > My question: is it normal this 1.3 sec init time? My system is 297
> > > > MHZ arm926ej-s with a 162MHZ DDR2 memory.
> > >
> > > It depends on where you start to measure it?
> > >     Starting from when power is turned on.
> > >     Starting from when the first instruction executes.
> > >     Start from the bootloader tries to load the kernel image.
> > > ...
> >
> > That number is relative, it is the time passing from u-boot jumping to
> > kernel and kernel starting.
> >
> > > I think this type of mearsurement  makes no much sense to you, since
> > > normally
> > > people want to know
> > >    When the kernel loads userspace or
> > >     When the first app starts to run.
> >
> > First application starts in ~4 second. This time consists of:
> >
> > 1) ~1 sec for application start.
> > 2) ~1 sec for userspace init, mouting filesys, etc.
> > 3) ~1 sec for kernel init for drivers and machine specific code
> > 4) ~1 sec for the aforementioned delay.
> >
> > > These are more meaningful for specific product.
> >
> > It is number 4 that I'm trying to understand. I think it has the highest
> > chance to contribute to end goal. But if it is as expected, then no room
> > for optimization there.
> 
> Well, "no room for optimization" is a pretty strong statement.  Last
> year Monta Vista demo the 1 second boot.
> 

What I'm looking for is whether early arm boot sequence is 1.3 secs or not. I 
may be wrong but my guess is before jumping to generic "start_kernel" function 
following files are executed:

* arch/arm/kernel/head.S
* arch/arm/kernel/head-common.S
* arch/arm/mm/proc-arm926.S

And these 3 files cost me 1.3 seconds. Initializing page tables, caches etc 
costing that much doesn't seem optimal to me. This is what I'm trying to find 
out.

> http://mvista.com/press_release_detail.php?fid=news/2009/Ultra-fast-boot.ht
> ml&d=
> 

This was an excellent paper and I stole all relevant parts from that paper. In 
addition to that I followed Tim Bird's excellent articles, Blackfin's articles 
related to 1 second boot. However, none of them references any boot delays 
related to this. They just do not spend this much time in their arch specific 
early boot.

Best regards,
Caglar

> I realized that it is a different and faster processor, but I'm pretty
> sure there are plenty of places you can trim the boot time.   It is a
> matter of time and effort.  You may want to start with the system
> requirement to see if 4 seconds is good enough and go from there.
> 
> Regards,
> 
> Steve
> 

Kernel Start-up Time

[Caglar Akyuz]

On Monday 18 January 2010 09:39:45 pm Dirk Behme wrote:
> On 18.01.2010 16:39, Steve Chen wrote:
> > On Mon, 2010-01-18 at 10:54 +0200, Caglar Akyuz wrote:
> >> On Monday 18 January 2010 10:39:27 am Tonyliu wrote:
> >>> Caglar Akyuz wrote:
> >>>> Hello,
> >>>>
> >>>> While measuring Linux start-up time, I see that printing version
> >>>> string in "start_kernel" takes ~1.3 seconds. I guess this is the time
> >>>> between from "bootloader jumping to uImage" and "printing version
> >>>> string in generic start_kernel code". Relevant part of my boot log is
> >>>> attached.
> >>>>
> >>>> My question: is it normal this 1.3 sec init time? My system is 297 MHZ
> >>>> arm926ej-s with a 162MHZ DDR2 memory.
> >>>
> >>> It depends on where you start to measure it?
> >>>      Starting from when power is turned on.
> >>>      Starting from when the first instruction executes.
> >>>      Start from the bootloader tries to load the kernel image.
> >>> ...
> >>
> >> That number is relative, it is the time passing from u-boot jumping to
> >> kernel and kernel starting.
> >>
> >>> I think this type of mearsurement  makes no much sense to you, since
> >>> normally
> >>> people want to know
> >>>     When the kernel loads userspace or
> >>>      When the first app starts to run.
> >>
> >> First application starts in ~4 second. This time consists of:
> >>
> >> 1) ~1 sec for application start.
> >> 2) ~1 sec for userspace init, mouting filesys, etc.
> >> 3) ~1 sec for kernel init for drivers and machine specific code
> >> 4) ~1 sec for the aforementioned delay.
> >>
> >>> These are more meaningful for specific product.
> >>
> >> It is number 4 that I'm trying to understand. I think it has the highest
> >> chance to contribute to end goal. But if it is as expected, then no room
> >> for optimization there.
> >
> > Well, "no room for optimization" is a pretty strong statement.  Last
> > year Monta Vista demo the 1 second boot.
> >
> > http://mvista.com/press_release_detail.php?fid=news/2009/Ultra-fast-boot.
> >html&d=
> >
> > I realized that it is a different and faster processor, but I'm pretty
> > sure there are plenty of places you can trim the boot time.   It is a
> > matter of time and effort.
> 
> Maybe
> 
> http://elinux.org/Boot_Time
> 
> could help you a little.
> 
> Best regards
> 
> Dirk
> 

Thanks Dirk,

That page was my starting point and following suggestions there I gained more 
than 10 seconds.

Unfortunately, my bottleneck is not mentioned in any of places. Either 
something is wrong with my setup or this is normal. I'm trying to understand 
which is the case.

Best regards,
Caglar

Kernel Start-up Time

[Russell King - ARM Linux]

On Tue, Jan 19, 2010 at 10:36:21AM +0200, Caglar Akyuz wrote:
> What I'm looking for is whether early arm boot sequence is 1.3 secs or not. I 
> may be wrong but my guess is before jumping to generic "start_kernel" function 
> following files are executed:
> 
> * arch/arm/kernel/head.S
> * arch/arm/kernel/head-common.S
> * arch/arm/mm/proc-arm926.S
> 
> And these 3 files cost me 1.3 seconds. Initializing page tables, caches etc 
> costing that much doesn't seem optimal to me. This is what I'm trying to find 
> out.

Only if your CPU is really inefficient when caches are turned off will
it take 1.3 seconds.

Try reading a cycle counter at the start of head.S, save it in memory.
Read it again in start_kernel() and save it somewhere again, and
compare the two values.  I think you'll find that it's not this code
which is taking 1.3 seconds.

Kernel Start-up Time

[Bahadir Balban]

Caglar Akyuz wrote:
> Hello,
> 
> While measuring Linux start-up time, I see that printing version string in 
> "start_kernel" takes ~1.3 seconds. I guess this is the time between from 
> "bootloader jumping to uImage" and "printing version string in generic 
> start_kernel code".

> Thanks,
> Caglar
> 
> _____________________________________________________________________ 
>                                                                                                                                                                   
> [    4.700896] Starting kernel ...                                                                                                                                                  
> [    4.702971]                                                                                                                                                                      
> [    5.966039] [    0.000000] Linux version 2.6.30-davinci1-06079-g4e73fae-

Hi Caglar,

This sounds like the kernel decompression is taking time. Have you tried
booting an uncompressed kernel? See if you can print on physical uart
address from files under arch/arm/boot/compressed

Thanks,

-- 
Bahadir

Kernel Start-up Time

[Johannes Stezenbach]

On Mon, Jan 18, 2010 at 10:10:01AM +0200, Caglar Akyuz wrote:
> 
> While measuring Linux start-up time, I see that printing version string in 
> "start_kernel" takes ~1.3 seconds. I guess this is the time between from 
> "bootloader jumping to uImage" and "printing version string in generic 
> start_kernel code". Relevant part of my boot log is attached.
> 
> My question: is it normal this 1.3 sec init time? My system is 297 MHZ 
> arm926ej-s with a 162MHZ DDR2 memory.

> [    4.700896] Starting kernel ...
> [    4.702971]
> [    5.966039] [    0.000000] Linux version 2.6.30-davinci1-06079-g4e73fae-

Actually printk goes to a buffer which is output only after the
serial console has been initialized (unless you use some
kind of early printk).  So to find out what causes the delay
look further down in your kernel messages, and look at the kernel
timestamps not the ptx_ts ones.


HTH
Johannes

Kernel Start-up Time

[Caglar Akyuz]

On Tuesday 19 January 2010 11:02:35 am Russell King - ARM Linux wrote:
> On Tue, Jan 19, 2010 at 10:36:21AM +0200, Caglar Akyuz wrote:
> > What I'm looking for is whether early arm boot sequence is 1.3 secs or
> > not. I may be wrong but my guess is before jumping to generic
> > "start_kernel" function following files are executed:
> >
> > * arch/arm/kernel/head.S
> > * arch/arm/kernel/head-common.S
> > * arch/arm/mm/proc-arm926.S
> >
> > And these 3 files cost me 1.3 seconds. Initializing page tables, caches
> > etc costing that much doesn't seem optimal to me. This is what I'm trying
> > to find out.
> 
> Only if your CPU is really inefficient when caches are turned off will
> it take 1.3 seconds.
> 
> Try reading a cycle counter at the start of head.S, save it in memory.
> Read it again in start_kernel() and save it somewhere again, and
> compare the two values.  I think you'll find that it's not this code
> which is taking 1.3 seconds.
> 

Thanks, you were right. This part is only taking 3 milliseconds. It turns out 
that my usage of early printk was wrong.

Caglar

Kernel Start-up Time

[Caglar Akyuz]

On Tuesday 19 January 2010 01:04:08 pm Johannes Stezenbach wrote:
> On Mon, Jan 18, 2010 at 10:10:01AM +0200, Caglar Akyuz wrote:
> > While measuring Linux start-up time, I see that printing version string
> > in "start_kernel" takes ~1.3 seconds. I guess this is the time between
> > from "bootloader jumping to uImage" and "printing version string in
> > generic start_kernel code". Relevant part of my boot log is attached.
> >
> > My question: is it normal this 1.3 sec init time? My system is 297 MHZ
> > arm926ej-s with a 162MHZ DDR2 memory.
> >
> > [    4.700896] Starting kernel ...
> > [    4.702971]
> > [    5.966039] [    0.000000] Linux version
> > 2.6.30-davinci1-06079-g4e73fae-
> 
> Actually printk goes to a buffer which is output only after the
> serial console has been initialized (unless you use some
> kind of early printk).  So to find out what causes the delay
> look further down in your kernel messages, and look at the kernel
> timestamps not the ptx_ts ones.
> 

I thought early prink was magically handling all this stuff. Passing 
'earlyprintk' option to the kernel revealed correct numbers.

Caglar

> 
> HTH
> Johannes
> 

Kernel Start-up Time

[Caglar Akyuz]

On Tuesday 19 January 2010 01:04:04 pm Bahadir Balban wrote:
> Caglar Akyuz wrote:
> > Hello,
> >
> > While measuring Linux start-up time, I see that printing version string
> > in "start_kernel" takes ~1.3 seconds. I guess this is the time between
> > from "bootloader jumping to uImage" and "printing version string in
> > generic start_kernel code".
> >
> > Thanks,
> > Caglar
> >
> > _____________________________________________________________________
> >
> > [    4.700896] Starting kernel ...
> > [    4.702971]
> > [    5.966039] [    0.000000] Linux version
> > 2.6.30-davinci1-06079-g4e73fae-
> 
> Hi Caglar,
> 
> This sounds like the kernel decompression is taking time. Have you tried
> booting an uncompressed kernel? See if you can print on physical uart
> address from files under arch/arm/boot/compressed
> 
> Thanks,
> 

Hi,

My image was uncompressed already. However, I was fooled by the printk delays. 
Learning proper use of early printk solved the issue.

Thanks,
Caglar