[patch] enhance initcall_debug, measure latency

[patch] enhance initcall_debug, measure latency

[Ingo Molnar]

Subject: [patch] enhance initcall_debug, measure latency
From: Ingo Molnar <mingo@elte.hu>

enhance the initcall_debug boot option:

 - measure the time the initcall took to execute and report
   it in units of milliseconds.

 - show the return code of initcalls (useful to see failures and
   to make sure that an initcall hung)

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 init/main.c |   17 +++++++++++++++++
 1 file changed, 17 insertions(+)

Index: linux/init/main.c
===================================================================
--- linux.orig/init/main.c
+++ linux/init/main.c
@@ -685,6 +685,7 @@ static void __init do_initcalls(void)
 	int count = preempt_count();
 
 	for (call = __initcall_start; call < __initcall_end; call++) {
+		ktime_t t0, t1, delta;
 		char *msg = NULL;
 		char msgbuf[40];
 		int result;
@@ -694,10 +695,26 @@ static void __init do_initcalls(void)
 			print_fn_descriptor_symbol(": %s()",
 					(unsigned long) *call);
 			printk("\n");
+			t0 = ktime_get();
 		}
 
 		result = (*call)();
 
+		if (initcall_debug) {
+			t1 = ktime_get();
+			delta = ktime_sub(t1, t0);
+
+			printk("initcall 0x%p", *call);
+			print_fn_descriptor_symbol(": %s()",
+					(unsigned long) *call);
+			printk(" returned %d.\n", result);
+
+			printk("initcall 0x%p ran for %Ld msecs: ",
+				*call, delta.tv64 >> 20);
+			print_fn_descriptor_symbol("%s()\n",
+				(unsigned long) *call);
+		}
+
 		if (result && result != -ENODEV && initcall_debug) {
 			sprintf(msgbuf, "error code %d", result);
 			msg = msgbuf;

Re: [patch] enhance initcall_debug, measure latency

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> Subject: [patch] enhance initcall_debug, measure latency
> From: Ingo Molnar <mingo@elte.hu>
> 
> enhance the initcall_debug boot option:
> 
>  - measure the time the initcall took to execute and report
>    it in units of milliseconds.

some boot time analysis using this facility:

with an allyesconfig bzImage kernel, here are all initcalls that took 
more than 10 msecs to execute (51 initcalls out of 1981). The list was 
generated via:

  dmesg | grep ' ran for ' | sort -r -n -t' ' -k +5

some entries (like old ISA drivers which have to auto-detect the hard 
way) are not a surprise. Some others, like eeprom_init() or 
acpi_pci_root_init(), are.

the 51 entries took 121.8 seconds to execute:

  echo `dmesg | grep ' ran for ' |
   sort -r -n -t' ' -k +5 | cut -d' ' -f5 |
   grep -vE '^..$|^.$'` | sed 's/ /+/g' | bc

  121822

while the other 1930 entries took only 8 seconds to execute:

  echo `dmesg | grep ' ran for ' |
   sort -r -n -t' ' -k +5 | cut -d' ' -f5 |
   grep -E '^..$|^.$'` | sed 's/ /+/g' | bc

  8265

so 93.6% of the allyesconfig bootup time is in 2.5% of the initcalls. If 
they were fixed then an allyesconfig bzImage, which would be capable to 
run on every PC known to mankind without any module whatsoever, would 
take around 10 seconds to boot up (which is acceptable for kernel bootup 
time).

	Ingo

initcall 0xc1f5487d ran for 23083 msecs: pca_isa_init+0x0/0x143()
initcall 0xc1f54fba ran for 17121 msecs: pcf8574_init+0x0/0x20()
initcall 0xc1f0c06f ran for 14710 msecs: net_olddevs_init+0x0/0x169()
initcall 0xc1f47582 ran for 10497 msecs: sjcd_init+0x0/0x3c5()
initcall 0xc1f54fda ran for 8560 msecs: pcf8591_init+0x0/0x44()
initcall 0xc1f54f5a ran for 8543 msecs: eeprom_init+0x0/0x20()
initcall 0xc1f479b4 ran for 6928 msecs: sony535_init+0x0/0x4e4()
initcall 0xc1f4720d ran for 5239 msecs: optcd_init+0x0/0x33b()
initcall 0xc1f54f9a ran for 4280 msecs: pca9539_init+0x0/0x20()
initcall 0xc1f3701d ran for 3248 msecs: init_this_scsi_driver+0x0/0xe1()
initcall 0xc1f2b387 ran for 3090 msecs: cadet_init+0x0/0x1c9()
initcall 0xc1f2b7ea ran for 1923 msecs: rtrack_init+0x0/0x125()
initcall 0xc1f2dabf ran for 1112 msecs: ide_init+0x0/0xe5()
initcall 0xc1f54f3a ran for 1070 msecs: ds1374_init+0x0/0x20()
initcall 0xc1f54f1a ran for 1070 msecs: ds1337_init+0x0/0x20()
initcall 0xc1f2767d ran for 958 msecs: init_bw_qcams+0x0/0x17()
initcall 0xc1f52549 ran for 851 msecs: sermouse_init+0x0/0x29()
initcall 0xc1f631ef ran for 582 msecs: i810_init_module+0x0/0xa7()
initcall 0xc1f1152d ran for 521 msecs: init_nic+0x0/0x3d()
initcall 0xc1f531bd ran for 507 msecs: spaceball_init+0x0/0x29()
initcall 0xc1f2e365 ran for 496 msecs: ide_generic_init+0x0/0x16()
initcall 0xc1f2765a ran for 484 msecs: cqcam_init+0x0/0x23()
initcall 0xc1f54644 ran for 452 msecs: nforce2_init+0x0/0x29()
initcall 0xc1ef3007 ran for 451 msecs: acpi_pci_root_init+0x0/0x2d()
initcall 0xc1f5320f ran for 433 msecs: stinger_init+0x0/0x29()
initcall 0xc1f4daa3 ran for 378 msecs: ohci_hcd_mod_init+0x0/0x73()
initcall 0xc1f55295 ran for 342 msecs: sensors_w83781d_init+0x0/0x45()
initcall 0xc1f55d1a ran for 336 msecs: sm_lm78_init+0x0/0x45()
initcall 0xc1ef5cbf ran for 303 msecs: isapnp_init+0x0/0x4a7()
initcall 0xc1f1fa80 ran for 292 msecs: com90xx_init+0x0/0x1026()
initcall 0xc1f4d9ff ran for 287 msecs: ehci_hcd_init+0x0/0x5d()
initcall 0xc1edd69f ran for 285 msecs: param_sysfs_init+0x0/0x191()
initcall 0xc1ef9f22 ran for 272 msecs: epca_module_init+0x0/0x434()
initcall 0xc1f3f4db ran for 262 msecs: init_this_scsi_driver+0x0/0xe1()
initcall 0xc1f04f5a ran for 247 msecs: serial8250_init+0x0/0x138()
initcall 0xc1ef314b ran for 210 msecs: acpi_pci_link_init+0x0/0x4b()
initcall 0xc1f56d1f ran for 196 msecs: raid5_init+0x0/0x3f()
initcall 0xc1f55e1f ran for 189 msecs: sensors_max1619_init+0x0/0x20()
initcall 0xc1f55d7f ran for 189 msecs: sensors_lm83_init+0x0/0x20()
initcall 0xc1f55476 ran for 188 msecs: sensors_adm1021_init+0x0/0x20()
initcall 0xc1ef65e3 ran for 185 msecs: pty_init+0x0/0x464()
initcall 0xc1f6b533 ran for 175 msecs: pci_acpi_init+0x0/0xb4()
initcall 0xc1f55cda ran for 168 msecs: sensors_lm75_init+0x0/0x20()
initcall 0xc1f55556 ran for 168 msecs: ds1621_init+0x0/0x20()
initcall 0xc1f554d6 ran for 168 msecs: sensors_adm1029_init+0x0/0x20()
initcall 0xc1f55d5f ran for 167 msecs: sensors_lm80_init+0x0/0x20()
initcall 0xc1f0bf7e ran for 147 msecs: fixed_init+0x0/0x53()
initcall 0xc1ef8aa5 ran for 125 msecs: cy_init+0x0/0x147d()
initcall 0xc1ef23d1 ran for 119 msecs: acpi_init+0x0/0x234()
initcall 0xc1f05b97 ran for 110 msecs: parport_pc_init+0x0/0x2d7()
initcall 0xc1f4b1f7 ran for 105 msecs: butterfly_init+0x0/0x17()

Re: [patch] enhance initcall_debug, measure latency

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> some boot time analysis using this facility:

using a non-allyesconfig kernel gives the results below. The entries 
that seem to take a bit too long (considering what they do):

initcall 0xc069bac5 ran for 519 msecs: init_nic+0x0/0x2c()
initcall 0xc0699610 ran for 344 msecs: isapnp_init+0x0/0x435()
initcall 0xc069af66 ran for 245 msecs: serial8250_init+0x0/0x112()
initcall 0xc06981e8 ran for 183 msecs: acpi_pci_link_init+0x0/0x43()
initcall 0xc06a07b0 ran for 175 msecs: pci_acpi_init+0x0/0x9b()
initcall 0xc06980ef ran for 110 msecs: acpi_pci_root_init+0x0/0x25()
initcall 0xc069fa24 ran for 69 msecs: pcibios_assign_resources+0x0/0x92()
initcall 0xc0246fd6 ran for 64 msecs: pci_init+0x0/0x2c()
initcall 0xc0695fc2 ran for 62 msecs: pcie_portdrv_init+0x0/0x46()
initcall 0xc0698656 ran for 54 msecs: pnp_system_init+0x0/0xf()
initcall 0xc06a27ac ran for 43 msecs: inet_init+0x0/0x390()
initcall 0xc069f88e ran for 28 msecs: init_acpi_pm_clocksource+0x0/0x173()

these amount to almost 50% of the ~4 seconds total bootup initcall time!

	Ingo

initcall 0xc069c43b ran for 1147 msecs: ide_init+0x0/0x8a()
initcall 0xc069bac5 ran for 519 msecs: init_nic+0x0/0x2c()
initcall 0xc069cbe0 ran for 497 msecs: ide_generic_init+0x0/0x11()
initcall 0xc0699610 ran for 344 msecs: isapnp_init+0x0/0x435()
initcall 0xc069af66 ran for 245 msecs: serial8250_init+0x0/0x112()
initcall 0xc06981e8 ran for 183 msecs: acpi_pci_link_init+0x0/0x43()
initcall 0xc06a07b0 ran for 175 msecs: pci_acpi_init+0x0/0x9b()
initcall 0xc06980ef ran for 110 msecs: acpi_pci_root_init+0x0/0x25()
initcall 0xc068b878 ran for 97 msecs: check_nmi_watchdog+0x0/0x1d1()
initcall 0xc069cbf1 ran for 75 msecs: idedisk_init+0x0/0xf()
initcall 0xc069fa24 ran for 69 msecs: pcibios_assign_resources+0x0/0x92()
initcall 0xc0246fd6 ran for 64 msecs: pci_init+0x0/0x2c()
initcall 0xc0695fc2 ran for 62 msecs: pcie_portdrv_init+0x0/0x46()
initcall 0xc0698656 ran for 54 msecs: pnp_system_init+0x0/0xf()
initcall 0xc06a27ac ran for 43 msecs: inet_init+0x0/0x390()
initcall 0xc069f88e ran for 28 msecs: init_acpi_pm_clocksource+0x0/0x173()
initcall 0xc069bb07 ran for 23 msecs: rtl8139_init_module+0x0/0x16()
initcall 0xc069eeae ran for 18 msecs: psmouse_init+0x0/0x64()
initcall 0xc0111a26 ran for 18 msecs: powernowk8_init+0x0/0x78()
initcall 0xc069e932 ran for 17 msecs: i8042_init+0x0/0x321()
initcall 0xc069baf1 ran for 16 msecs: cp_init+0x0/0x16()
initcall 0xc06979b8 ran for 16 msecs: acpi_init+0x0/0x1ff()
initcall 0xc0697bfc ran for 15 msecs: acpi_scan_init+0x0/0xfc()
initcall 0xc06a3154 ran for 12 msecs: netlbl_init+0x0/0x71()
initcall 0xc069e512 ran for 11 msecs: usb_init+0x0/0x103()
initcall 0xc06986cd ran for 11 msecs: pnpacpi_init+0x0/0x69()

Re: [patch] enhance initcall_debug, measure latency

[Andi Kleen]

Ingo Molnar <mingo@elte.hu> writes:

> so 93.6% of the allyesconfig bootup time is in 2.5% of the initcalls. If 
> they were fixed then an allyesconfig bzImage, which would be capable to 
> run on every PC known to mankind without any module whatsoever, would 

Assuming that every PC has enough memory @) Allyes is >35MB

> take around 10 seconds to boot up (which is acceptable for kernel bootup 
> time).

It might make sense to measure idle ticks vs busy ticks too.
If it's idle cycles perhaps things can be more easily fixed by multi threading
the initialization. If it's busy cycles perhaps they can be converted
into sleeping cycles.

Perhaps you should tell the individual maintainers for those?
If they still have one. A lot of them look like old hardware
where there might be no working ones left, perhaps just deprecation
would make sense.

> initcall 0xc1f5487d ran for 23083 msecs: pca_isa_init+0x0/0x143()
> initcall 0xc1f54fba ran for 17121 msecs: pcf8574_init+0x0/0x20()

e.g. those just look like bugs.

> initcall 0xc1f0c06f ran for 14710 msecs: net_olddevs_init+0x0/0x169()

That's many drivers initialized together for compatibility ordering reasons.

-Andi

Re: [patch] enhance initcall_debug, measure latency

[Ingo Molnar]

* Andi Kleen <andi@firstfloor.org> wrote:

> Ingo Molnar <mingo@elte.hu> writes:
> 
> > so 93.6% of the allyesconfig bootup time is in 2.5% of the 
> > initcalls. If they were fixed then an allyesconfig bzImage, which 
> > would be capable to run on every PC known to mankind without any 
> > module whatsoever, would
> 
> Assuming that every PC has enough memory @) Allyes is >35MB

yes :)

> > take around 10 seconds to boot up (which is acceptable for kernel 
> > bootup time).
> 
> It might make sense to measure idle ticks vs busy ticks too. If it's 
> idle cycles perhaps things can be more easily fixed by multi threading 
> the initialization. If it's busy cycles perhaps they can be converted 
> into sleeping cycles.
> 
> Perhaps you should tell the individual maintainers for those? If they 
> still have one. A lot of them look like old hardware where there might 
> be no working ones left, perhaps just deprecation would make sense.

note that i have done another run today too, with common drivers (see 
the same thread).

But obviously it doesnt really scale for me to notify every maintainer, 
we've basically got no infrastructure to bulk-mail maintainers based on 
a list of symbols. (maybe git could be extended to know about things 
like who-owns-this-and-that-file? Or the source could be annotated so 
that automated tools could parse it out.) So i did the notification the 
usual way: by mailing to lkml ;-)

> > initcall 0xc1f5487d ran for 23083 msecs: pca_isa_init+0x0/0x143() 
> > initcall 0xc1f54fba ran for 17121 msecs: pcf8574_init+0x0/0x20()
> 
> e.g. those just look like bugs.

it's ok i think: it's ISA so it spends its time fairly to tickle the 
ports in a loop.

	Ingo

Re: [patch] enhance initcall_debug, measure latency

[Andi Kleen]

> > > initcall 0xc1f5487d ran for 23083 msecs: pca_isa_init+0x0/0x143() 
> > > initcall 0xc1f54fba ran for 17121 msecs: pcf8574_init+0x0/0x20()
> > 
> > e.g. those just look like bugs.
> 
> it's ok i think: it's ISA so it spends its time fairly to tickle the 
> ports in a loop.

23 or 17 seconds long?  That's just broken imho.

I presume one could define a background_module_init() for those, 
but it's still buggy.

-Andi

Re: [patch] enhance initcall_debug, measure latency

[Andrew Morton]

On Sun, 1 Apr 2007 20:16:14 +0200 Ingo Molnar <mingo@elte.hu> wrote:

> +		if (initcall_debug) {
> +			t1 = ktime_get();
> +			delta = ktime_sub(t1, t0);
> +
> +			printk("initcall 0x%p", *call);
> +			print_fn_descriptor_symbol(": %s()",
> +					(unsigned long) *call);
> +			printk(" returned %d.\n", result);
> +
> +			printk("initcall 0x%p ran for %Ld msecs: ",
> +				*call, delta.tv64 >> 20);
> +			print_fn_descriptor_symbol("%s()\n",
> +				(unsigned long) *call);
> +		}

This might come out a bit better if it were to use -mm's
sprint_symbol().