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;
-

[ message continues ]

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: ...
[ message continues ]

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 ...
[ message continues ]

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


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

-Andi

-

[ message continues ]

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 

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

	Ingo
-

[ message continues ]

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
-

[ message continues ]

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

[ message continues ]