From: eLinux.org

Initcall Debug

Introduction

Passing the option “initcall_debug” on the kernel command line will
cause timing information to be printed to the console for each initcall.
initcalls are used to initialize statically linked kernel drivers and
subsystems and contribute a significant amount of time to the Linux boot
process. The output looks like this:

  1. calling ipc_init+0x0/0x28 @ 1
  2. msgmni has been set to 42
  3. initcall ipc_init+0x0/0x28 returned 0 after 1872 usecs

You can use ‘dmesg’ to see the messages after the kernel has booted.
With a short ‘sed’ script, you can reorder the final ‘timing’ line, and
sort the initcalls numerically by duration. Here is a command to do
this:

  1. dmesg -s 128000 | grep "initcall" | sed "s/\(.*\)after\(.*\)/\2 \1/g" | sort -n

Sample output

Here is some sample output from the above command sequence. This was on
an old X86-based desktop system. Printk
Times was turned on (hence the extra
timestamp on each line.)

  1. 24 msecs [ 2.237177] initcall acpi_button_init+0x0/0x51 returned 0
  2. 28 msecs [ 0.763503] initcall init_acpi_pm_clocksource+0x0/0x16c
  3. returned 0
  4. 32 msecs [ 0.348241] initcall acpi_pci_link_init+0x0/0x43 returned 0
  6. 33 msecs [ 0.919004] initcall inet_init+0x0/0x1c7 returned 0
  7. 33 msecs [ 5.282722] initcall psmouse_init+0x0/0x5e returned 0
  8. 54 msecs [ 2.979825] initcall e100_init_module+0x0/0x4d returned 0
  9. 71 msecs [ 0.650325] initcall pnp_system_init+0x0/0xf returned 0
  10. 91 msecs [ 0.872402] initcall pcibios_assign_resources+0x0/0x85
  11. returned 0
  12. 187 msecs [ 4.369187] initcall ehci_hcd_init+0x0/0x70 returned 0
  13. 245 msecs [ 2.777161] initcall serial8250_init+0x0/0x100 returned 0
  14. 673 msecs [ 5.098052] initcall uhci_hcd_init+0x0/0xc1 returned 0
  15. 830 msecs [ 4.067279] initcall piix_init+0x0/0x27 returned 0
  16. 1490 msecs [ 8.290606] initcall ip_auto_config+0x0/0xd70 returned 0

Notes

Using initcall_debug increases the amount of messages produced by the
kernel during system boot. It’s a good idea to increase the printk log
buffer size to avoid overflowing the log buffer. To do this, increase
the value of CONFIG_LOG_BUF_SHIFT from 14 to 18. This increases the
log buffer from the default size of 16k to 256K.

You will need to enable CONFIG_PRINTK_TIME and CONFIG_KALLSYMS in
your kernel configuration for this to work correctly. The first option
displays printk timings and the second option ensures that function
names are printed rather than memory addresses.

Categories: