How to debug kernel startup time?

How to debug kernel startup time?

[Corrado Zoccolo]

Hi,
I'm seeing around 2 s "lost" during kernel boot, that are not
accounted for any init call (excerpt of dmesg with initcall_debug
follows, kernel is 2.6.29).
What's the suggested way to investigate such problems?

Thanks,
Corrado

[    1.797146] calling  tcp_congestion_default+0x0/0xf @ 1
[    1.797279] initcall tcp_congestion_default+0x0/0xf returned 0 after 48 usecs
[    1.911721] mmc0: new SDHC card at address b368
[    1.912155] mmcblk0: mmc0:b368 SDC   7.46 GiB
[    1.912293]  mmcblk0: p1
[    2.095702] usb 1-5: New USB device found, idVendor=064e, idProduct=d101
[    2.095801] usb 1-5: New USB device strings: Mfr=3, Product=1, SerialNumber=4
[    2.095902] usb 1-5: Product: Acer Crystal Eye webcam
[    2.095980] usb 1-5: Manufacturer: SuYin
[    2.096053] usb 1-5: SerialNumber: CN0316-M608-OV01-VA-R02.00.00
[    2.096440] usb 1-5: configuration #1 chosen from 1 choice
[    2.500110] Clocksource tsc unstable (delta = -282878412 ns)
[    3.946532] Synaptics Touchpad, model: 1, fw: 7.2, id: 0x1c0b1,
caps: 0xd04771/0xa40000
[    4.005707] input: SynPS/2 Synaptics TouchPad as /class/input/input7
[    4.540135] async_waiting @ 1
[    4.540226] async_continuing @ 1 after 1 usec
[    4.544604] kjournald starting.  Commit interval 5 seconds
[    4.544697] EXT3-fs: mounted filesystem with ordered data mode.
[    4.544792] VFS: Mounted root (ext3 filesystem) readonly on device 8:1.
[    4.544917] async_waiting @ 1
[    4.544991] async_continuing @ 1 after 1 usec
[    4.545222] Freeing unused kernel memory: 276k freed
[    4.545430] Write protecting the kernel text: 3128k
[    4.545576] Write protecting the kernel read-only data: 1480k

-- 
__________________________________________________________________________

dott. Corrado Zoccolo                          mailto:czoccolo@gmail.com
PhD - Department of Computer Science - University of Pisa, Italy
--------------------------------------------------------------------------

Re: How to debug kernel startup time?

[Arjan van de Ven]

On Sun, 29 Mar 2009 17:40:10 +0200
Corrado Zoccolo <czoccolo@gmail.com> wrote:

> Hi,
> I'm seeing around 2 s "lost" during kernel boot, that are not
> accounted for any init call (excerpt of dmesg with initcall_debug
> follows, kernel is 2.6.29).
> What's the suggested way to investigate such problems?

I take it you don't have an initrd ?

If so I know what you are hitting; I have a patch to solve it but it's
a bit convoluted and not ready for mainline.... let me know if you want
to try it, I suspect it'll solve your issue ;)

Re: How to debug kernel startup time?

[Corrado Zoccolo]

On Sun, Mar 29, 2009 at 5:51 PM, Arjan van de Ven <arjan@infradead.org> wrote:
> On Sun, 29 Mar 2009 17:40:10 +0200
> Corrado Zoccolo <czoccolo@gmail.com> wrote:
>
>> Hi,
>> I'm seeing around 2 s "lost" during kernel boot, that are not
>> accounted for any init call (excerpt of dmesg with initcall_debug
>> follows, kernel is 2.6.29).
>> What's the suggested way to investigate such problems?
>
> I take it you don't have an initrd ?

You guessed right.

>
> If so I know what you are hitting; I have a patch to solve it but it's
> a bit convoluted and not ready for mainline.... let me know if you want
> to try it, I suspect it'll solve your issue ;)
>

Sure. I'd like to test it.

Thanks,
Corrado

-- 
__________________________________________________________________________

dott. Corrado Zoccolo                          mailto:czoccolo@gmail.com
PhD - Department of Computer Science - University of Pisa, Italy
--------------------------------------------------------------------------

Re: How to debug kernel startup time?

[Arjan van de Ven]

[-- Attachment #1: Type: text/plain, Size: 971 bytes --]

On Sun, 29 Mar 2009 18:45:36 +0200
Corrado Zoccolo <czoccolo@gmail.com> wrote:

> On Sun, Mar 29, 2009 at 5:51 PM, Arjan van de Ven
> <arjan@infradead.org> wrote:
> > On Sun, 29 Mar 2009 17:40:10 +0200
> > Corrado Zoccolo <czoccolo@gmail.com> wrote:
> >
> >> Hi,
> >> I'm seeing around 2 s "lost" during kernel boot, that are not
> >> accounted for any init call (excerpt of dmesg with initcall_debug
> >> follows, kernel is 2.6.29).
> >> What's the suggested way to investigate such problems?
> >
> > I take it you don't have an initrd ?
> 
> You guessed right.
> 
> >
> > If so I know what you are hitting; I have a patch to solve it but
> > it's a bit convoluted and not ready for mainline.... let me know if
> > you want to try it, I suspect it'll solve your issue ;)
> >
> 
> Sure. I'd like to test it.
> 

attached...

-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

[-- Attachment #2: linux-2.6.29-dont-wait-for-mouse.patch --]
[-- Type: text/x-patch, Size: 1359 bytes --]

Subject: [PATCH] fastboot: remove "wait for all devices before mounting root" delay

In the non-initrd case, we wait for all devices to finish their
probing before we try to mount the rootfs.
In practice, this means that we end up waiting 2 extra seconds for
the PS/2 mouse probing even though the root holding device has been
ready since a long time.

The previous two patches in this series made the RAID autodetect code
do it's own "wait for probing to be done" code, and added
"wait and retry" functionality in case the root device isn't actually
available.

These two changes should make it safe to remove the delay itself,
and this patch does this. On my test laptop, this reduces the boot time
by 2 seconds (kernel time goes from 3.9 to 1.9 seconds).

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
---
--- a/init/do_mounts.c	2009-01-07 18:42:10.000000000 -0800
+++ b/init/do_mounts.c	2009-01-07 18:43:02.000000000 -0800
@@ -370,14 +370,17 @@ void __init prepare_namespace(void)
 		ssleep(root_delay);
 	}
 
+#if 0
 	/*
 	 * wait for the known devices to complete their probing
 	 *
 	 * Note: this is a potential source of long boot delays.
 	 * For example, it is not atypical to wait 5 seconds here
 	 * for the touchpad of a laptop to initialize.
 	 */
 	wait_for_device_probe();
+#endif
+	async_synchronize_full();
 
 	md_run_setup();
 


[-- Attachment #3: linux-2.6.29-retry-root-mount.patch --]
[-- Type: text/x-patch, Size: 1923 bytes --]

Subject: [PATCH] fastboot: retry mounting the root fs if we can't find init

currently we wait until all device init is done before trying to mount
the root fs, and to consequently execute init.

In preparation for relaxing the first delay, this patch adds a retry
attempt in case /sbin/init is not found. Before retrying, the code
will wait for all device init to complete.

While this patch by itself doesn't gain boot time yet (it needs follow on
patches), the alternative already is to panic()...

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
---
--- a/init/main.c	2009-01-07 18:29:11.000000000 -0800
+++ b/init/main.c	2009-01-07 18:32:08.000000000 -0800
@@ -837,6 +837,7 @@ static void run_init_process(char *init_
  */
 static noinline int init_post(void)
 {
+	int retry_count = 1;
 	/* need to finish all async __init code before freeing the memory */
 	async_synchronize_full();
 	free_initmem();
@@ -859,6 +860,8 @@ static noinline int init_post(void)
 				ramdisk_execute_command);
 	}
 
+retry:
+
 	/*
 	 * We try each of these until one succeeds.
 	 *
@@ -871,6 +874,23 @@ static noinline int init_post(void)
 					"defaults...\n", execute_command);
 	}
 	run_init_process("/sbin/init");
+
+        if (retry_count > 0) {
+               retry_count--;
+               /* 
+                * We haven't found init yet... potentially because the device
+                * is still being probed. We need to
+                * - flush keventd and friends
+                * - wait for the known devices to complete their probing
+                * - try to mount the root fs again
+                */
+               flush_scheduled_work();
+               while (driver_probe_done() != 0)
+                       msleep(100);
+               prepare_namespace();
+               goto retry;
+        }
+
 	run_init_process("/etc/init");
 	run_init_process("/bin/init");
 	run_init_process("/bin/sh");

Re: How to debug kernel startup time?

[Corrado Zoccolo]

On Sun, Mar 29, 2009 at 6:59 PM, Arjan van de Ven <arjan@infradead.org> wrote:
> On Sun, 29 Mar 2009 18:45:36 +0200
> Corrado Zoccolo <czoccolo@gmail.com> wrote:
>
>> On Sun, Mar 29, 2009 at 5:51 PM, Arjan van de Ven
>> <arjan@infradead.org> wrote:
>> > On Sun, 29 Mar 2009 17:40:10 +0200
>> > Corrado Zoccolo <czoccolo@gmail.com> wrote:
>> >
>> >> Hi,
>> >> I'm seeing around 2 s "lost" during kernel boot, that are not
>> >> accounted for any init call (excerpt of dmesg with initcall_debug
>> >> follows, kernel is 2.6.29).
>> >> What's the suggested way to investigate such problems?
>> >
>> > I take it you don't have an initrd ?
>>
>> You guessed right.
>>
>> >
>> > If so I know what you are hitting; I have a patch to solve it but
>> > it's a bit convoluted and not ready for mainline.... let me know if
>> > you want to try it, I suspect it'll solve your issue ;)
>> >
>>
>> Sure. I'd like to test it.
>>
>
> attached...

They worked fine. With fastboot enabled + some ACPI patch that alexei
is working on, I can now boot the kernel in 1.7s.

Corrado

>
> --
> Arjan van de Ven        Intel Open Source Technology Centre
> For development, discussion and tips for power savings,
> visit http://www.lesswatts.org
>



-- 
__________________________________________________________________________

dott. Corrado Zoccolo                          mailto:czoccolo@gmail.com
PhD - Department of Computer Science - University of Pisa, Italy
--------------------------------------------------------------------------
The self-confidence of a warrior is not the self-confidence of the average
man. The average man seeks certainty in the eyes of the onlooker and calls
that self-confidence. The warrior seeks impeccability in his own eyes and
calls that humbleness.
                               Tales of Power - C. Castaneda