I’m on vacation, but I can’t resist playing with new toys, seeing as Santa didn’t bring me anything fun this year. In my previous post, I mentioned that 2.6.28 was for the most part, dull. Reading the excellent changelog summary at kernelnewbies, I noticed a new feature I had until now overlooked.

1.6. Boot tracer

The purpose of this tracer is to helps developers to optimize boot times: it records the timings of the initcalls. Its aim is to be parsed by the scripts/bootgraph.pl tool to produce graphics about boot inefficiencies, giving a visual representation of the delays during initcalls. Users need to enable CONFIG_BOOT_TRACER, boot with the “initcall_debug” and “printk.time=1″ parameters, and run “dmesg | perl scripts/bootgraph.pl > output.svg” to generate the final data.

Very interesting.

Here’s what it looks like when I ran it on my eeepc ..

boot tracing output.

Looks pretty. Though something isn’t quite right.
If you look at the dmesg output, there are over 400 initcalls. Even if we ignore all the uninteresting ones that return in 0 usecs, there’s still over 300 in the log. What gives?
The script stops parsing once the kernel hands off to the early userspace scripts in initramfs. So everything from the ‘Write protecting the kernel’ message at 8 seconds into the bootup is ignored. (Sidenote: The fact that we’re taking 8 seconds just to get to this stage _sucks_, more on that another time). So all the later modules that get loaded aren’t part of this picture.

My perl is a little rusty so I didn’t spot how it does it, but it seems there’s a threshold at which it ignores the initcalls that return quickly. Of those reported in the graph, the ‘fastest’ was ehci_hcd_init at 126837. acpi_init was almost in the same ballpark at 106445, but didn’t get picked up.

Whilst these big hitters are no doubt damaging to the boot time, it’s important to note the cumulative effect of all those five-figure initcalls.

No related posts.

Related posts brought to you by Yet Another Related Posts Plugin.