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:

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

(Or use the sort-initcalls.sh tool described below)

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

Work in progress

Tim Bird has recently (as of August 2024) been working on an updated version of the program scripts/show_delta, which parses dmesg printk timing results, and aggregates results for different classes of printk messages, including those for initcall data.

See Deferred_Initcalls for a patch that allows deferring an initcall to later in the boot sequence.

Notes

Increasing the kernel log buffer size

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. The easiest way to do this is to add the following to the kernel command line: 'log_buf_len=20M"

An alternate way to increase the log buffer size is to change the value of CONFIG_LOG_BUF_SHIFT and re-compiling the kernel. For example, changing the value from 14 to 20 increases the log buffer to approximately 1M.

Suggested kernel configs

You should enable CONFIG_KALLSYMS in your kernel configuration to ensures that function names are printed rather than memory addresses.

If you are doing boot-time work with the kernel, you probably already have CONFIG_PRINTK_TIMES set. This option puts a timestamp on each kernel message indicating the time (after clock initialization) when the printk() call occurred.

Resources

Here are some other references and tutorials for using initcall_debug:

* https://www.collabora.com/news-and-blog/blog/2020/07/14/introduction-to-linux-kernel-initcalls/

Tools

You can use the tool "sort-initcalls.sh" to show a sorted list of initcall lines from your dmesg output. See File:Sort-initcalls.sh

To use this download the file, chmod a+x it, run dmesg saving results into a file, and then run the sort-initcalls.sh script with your dmesg file.