Difference between revisions of "Initcall Debug"
WillNewton (talk | contribs) |
m (Updated kernel config option for current kernel.) |
||
(10 intermediate revisions by 3 users not shown) | |||
Line 1: | Line 1: | ||
== Introduction == | == Introduction == | ||
− | Passing the initcall_debug | + | 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: |
<pre> | <pre> | ||
Line 8: | Line 8: | ||
initcall ipc_init+0x0/0x28 returned 0 after 1872 usecs | initcall ipc_init+0x0/0x28 returned 0 after 1872 usecs | ||
</pre> | </pre> | ||
+ | |||
+ | 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: | ||
+ | |||
+ | 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.) | ||
+ | |||
+ | <div style="margin:0; margin-top:10px; margin-right:10px; border:1px solid #dfdfdf; padding:0 1em 1em 1em; background-color:#ffffcc; align:right; "> | ||
+ | 24 msecs [ 2.237177] initcall acpi_button_init+0x0/0x51 returned 0 | ||
+ | <br>28 msecs [ 0.763503] initcall init_acpi_pm_clocksource+0x0/0x16c returned 0 | ||
+ | <br>32 msecs [ 0.348241] initcall acpi_pci_link_init+0x0/0x43 returned 0 | ||
+ | <br>33 msecs [ 0.919004] initcall inet_init+0x0/0x1c7 returned 0 | ||
+ | <br>33 msecs [ 5.282722] initcall psmouse_init+0x0/0x5e returned 0 | ||
+ | <br>54 msecs [ 2.979825] initcall e100_init_module+0x0/0x4d returned 0 | ||
+ | <br>71 msecs [ 0.650325] initcall pnp_system_init+0x0/0xf returned 0 | ||
+ | <br>91 msecs [ 0.872402] initcall pcibios_assign_resources+0x0/0x85 returned 0 | ||
+ | <br>187 msecs [ 4.369187] initcall ehci_hcd_init+0x0/0x70 returned 0 | ||
+ | <br>245 msecs [ 2.777161] initcall serial8250_init+0x0/0x100 returned 0 | ||
+ | <br>673 msecs [ 5.098052] initcall uhci_hcd_init+0x0/0xc1 returned 0 | ||
+ | <br>830 msecs [ 4.067279] initcall piix_init+0x0/0x27 returned 0 | ||
+ | <br>1490 msecs [ 8.290606] initcall ip_auto_config+0x0/0xd70 returned 0 | ||
+ | </div> | ||
+ | |||
+ | == 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. | ||
+ | [[Category:Boot Time]] | ||
+ | [[Category:Kernel]] |
Latest revision as of 09:08, 12 November 2012
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:
calling ipc_init+0x0/0x28 @ 1 msgmni has been set to 42 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:
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.)
24 msecs [ 2.237177] initcall acpi_button_init+0x0/0x51 returned 0
28 msecs [ 0.763503] initcall init_acpi_pm_clocksource+0x0/0x16c returned 0
32 msecs [ 0.348241] initcall acpi_pci_link_init+0x0/0x43 returned 0
33 msecs [ 0.919004] initcall inet_init+0x0/0x1c7 returned 0
33 msecs [ 5.282722] initcall psmouse_init+0x0/0x5e returned 0
54 msecs [ 2.979825] initcall e100_init_module+0x0/0x4d returned 0
71 msecs [ 0.650325] initcall pnp_system_init+0x0/0xf returned 0
91 msecs [ 0.872402] initcall pcibios_assign_resources+0x0/0x85 returned 0
187 msecs [ 4.369187] initcall ehci_hcd_init+0x0/0x70 returned 0
245 msecs [ 2.777161] initcall serial8250_init+0x0/0x100 returned 0
673 msecs [ 5.098052] initcall uhci_hcd_init+0x0/0xc1 returned 0
830 msecs [ 4.067279] initcall piix_init+0x0/0x27 returned 0
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.