Embedded Linux Boot Time — Part 2: Measuring the Kernel and User Space

A driver reports 412 milliseconds in initcall_debug. You open the source, go looking for the expensive loop, and find nothing that could possibly take 412 milliseconds. There is a good reason for that. The driver executed about five milliseconds of code. It spent the rest of the time blocked.

That single case describes most kernel boot time work. The instrumentation is easy to switch on and easy to misread. The same holds one phase later, where the first command almost everyone runs on a systemd image is the one systemd’s own documentation warns you about.

Where these two phases sit

A board spends its boot time in four phases, each with its own clock starting at zero: ROM and SPL, the bootloader, the kernel, and user space. Phases 3 and 4 are what this article measures. The first two are covered in an earlier article on the four boot phases and measuring the bootloader.

Keep one thing in mind throughout: the dmesg timestamp of 0.000000 is not power-on. It is the moment the kernel started running and printk timestamping became available. If your requirement is written from power-on, the numbers here are part of your answer rather than all of it.

Measuring the kernel with initcall_debug

The kernel’s own instrumentation is one boot parameter. Add initcall_debug to the command line and it logs the entry and exit of every initcall, with a duration.

raghu@techveda.org:~$ cat /proc/cmdline
console=ttymxc0,115200 root=/dev/mmcblk2p2 rw rootwait initcall_debug ignore_loglevel printk.time=1

Two details are easy to miss. The lines print at KERN_DEBUG, so they are always in the ring buffer and dmesg shows them, but they will not reach the console unless you raise the level with loglevel=8 or ignore_loglevel. And symbol names come from CONFIG_KALLSYMS; without it you get raw addresses.

The runtime toggle that does not work

The parameter appears at /sys/module/kernel/parameters/initcall_debug with mode 0644, which makes it look like you can switch it on later to time module inits. On a normal kernel you cannot, and this is worth knowing before you waste an hour on it.

initcall_debug is implemented by registering callbacks on the initcall_start, initcall_finish and initcall_level tracepoints. With CONFIG_TRACEPOINTS=y, which is the normal case, initcall_debug_enable() runs exactly once from start_kernel(), and only if the parameter was already set on the command line:

	/* Trace events are available after this */
	trace_init();

	if (initcall_debug)
		initcall_debug_enable();

Writing 1 to the sysfs file afterwards sets the variable and registers nothing, so no output appears for modules loaded later. The reverse is also true: if you booted with the parameter and write 0, the callbacks stay registered and the printks keep coming, because the callbacks never re-check the variable.

To time module inits at runtime, enable the tracepoints directly instead.

raghu@techveda.org:~$ echo 1 > /sys/kernel/tracing/events/initcall/enable

The one configuration where the sysfs toggle does work is CONFIG_TRACEPOINTS=n, where the wrappers fall back to calling the same callbacks directly and test the variable on each call. That is not a kernel most people ship.

Reading the output

Sort by the duration field, not the timestamp. The duration is the second-to-last field on each line, so let awk count in from the end rather than using a fixed field number. That detail matters: once a timestamp grows from one digit to two, a fixed field number starts selecting the wrong column.

raghu@techveda.org:~$ dmesg | grep 'initcall .* returned' |
    awk '{print $(NF-1), $0}' | sort -rn | cut -d' ' -f2- | head -6
[    1.362945] initcall mmc_blk_init+0x0/0x84 returned 0 after 412831 usecs
[    0.903114] initcall imx_pcie_init+0x0/0x2c returned 0 after 203114 usecs
[    1.496422] initcall regulator_init_complete+0x0/0x30 returned 0 after 96422 usecs
[    0.578210] initcall usb_init+0x0/0x148 returned 0 after 58210 usecs
[    1.531044] initcall clk_disable_unused+0x0/0x120 returned 0 after 21044 usecs
[    0.318880] initcall netlink_proto_init+0x0/0x120 returned 0 after 9871 usecs

The timestamps in that list are not in time order, and that is expected. The timestamp records when an initcall finished, and initcalls run in level order — core, postcore, arch, subsys, fs, device, late — not in order of cost. The after N usecs figure is wall time, and it includes anything the initcall waited for.

For a chart rather than a ranking, the kernel tree ships scripts/bootgraph.pl, which needs CONFIG_PRINTK_TIME and parses the same dmesg text:

raghu@techveda.org:~$ dmesg | perl scripts/bootgraph.pl > boot.svg

What it shows that a sorted list cannot is overlap and gaps. Pay attention to the gaps. A gap is time the kernel spent outside any initcall — decompressing itself, or waiting for the root device to appear, which is what rootwait tells it to do.

Why a long initcall is usually a blocked initcall

An initcall reporting 412 ms is rarely executing 412 ms of code. Something inside it blocked.

The causes are ordinary. A probe calls request_firmware() and waits. A regulator is enabled and the driver waits out the ramp delay declared for it. A bus is scanned, and a device that is not fitted takes the full timeout to not answer. A driver calls msleep() because the datasheet asks for a settling time. In each case the duration is real, and none of it is code you can speed up by reading it more carefully. You have to find what the initcall waited for, not what it executed.

Function graph tracing is the direct way to look inside one. Take the worst entry from your sorted list, trace that function, and the long leaf is usually obvious:

raghu@techveda.org:~$ cd /sys/kernel/tracing
raghu@techveda.org:~$ echo function_graph > current_tracer
raghu@techveda.org:~$ echo mmc_blk_init > set_graph_function

To test whether an initcall really is the cost before changing any code, initcall_blacklist=fn1,fn2 skips named initcalls. It needs CONFIG_KALLSYMS, and do_one_initcall() returns -EPERM without running the function at all. For a built-in that return value is discarded, so the initcall is silently skipped; for a module it fails the load. It is a diagnostic tool, not a shipping configuration.

Deferred probe is a different problem

Deferred probe gets mentioned alongside slow initcalls often enough that the two get confused. They behave differently, and the fix is different.

When a driver’s probe() finds a dependency missing, it returns -EPROBE_DEFER at that point. Usually that happens early and cheaply, while the driver is acquiring its clocks and regulators, so it rarely accounts for a long initcall duration. It is not a guarantee — a probe that does slow work before it reaches the missing dependency will still be charged for that work — but a device that defers is not normally the entry at the top of your sorted list. What it produces instead is a device that is not usable yet. The driver core puts it on a list and retries as new drivers register.

The cost lands somewhere else: your application waits on a device that appears late, the retry work runs after the initcalls have finished, or deferred_probe_timeout= expires and the device never appears at all. That parameter bounds how long the core keeps trying, and its default comes from CONFIG_DRIVER_DEFERRED_PROBE_TIMEOUT — 0 when modules are disabled, 10 when they are enabled.

Anything still unresolved is visible. Read this file to answer the question “which devices never probed”, not to explain a slow initcall:

raghu@techveda.org:~$ cat /sys/kernel/debug/devices_deferred
30800000.spba-bus:serial@30890000     imx-uart
32c00000.bus:blk-ctrl                 imx8m-blk-ctrl

A device listed there has not probed. The fix is to make its supplier available, usually by correcting the order in which the device tree describes them. Optimizing inside the consumer driver will not help, because the consumer has not run. One caveat: the file is a snapshot of what is still pending, so an empty file does not prove that nothing deferred earlier in the boot.

We covered the retry machinery in our article on deferred probe in the Linux kernel, and the driver-side resource handling it interacts with in devres and managed device resources.

Measuring user space with systemd-analyze

Once init is running, the tooling changes.

raghu@techveda.org:~$ systemd-analyze time
Startup finished in 1.361s (kernel) + 287ms (initrd) + 2.949s (userspace) = 4.597s
multi-user.target reached after 2.844s in userspace.

That is the phase split. To find what to change, use the critical chain:

raghu@techveda.org:~$ systemd-analyze critical-chain
multi-user.target @2.844s
└─myapp.service @2.611s +233ms
  └─network-online.target @2.601s
    └─systemd-networkd-wait-online.service @0.719s +1.881s
      └─systemd-networkd.service @0.664s +51ms
        └─dbus.socket @0.658s

The @ is when a unit became active; the + is how long it took to start. This chain is unambiguous. systemd-networkd-wait-online.service spent 1.881 seconds waiting for a link. That is not a service to optimize. It is a dependency to delete. If the application does not need the network before it starts, network-online.target should not be in its After= list. systemd-analyze plot > boot.svg gives the same data as a chart, which is easier to read when several units run in parallel.

Why blame is the wrong first command

systemd-analyze blame sorts units by how long they took to start, and it is what almost everyone runs first. The systemd documentation says plainly why that is a problem: a unit can appear slow purely because it was waiting for another unit to finish. The manual lists further limits of its own, including how blame treats Type=simple services and time spent outside the activating state.

So the unit at the top of blame may not be on the critical path at all. Start with critical-chain. Then come back to blame and read it differently, as a list of units that are expensive but not blocking anything yet. Those are what you fix next, after the current bottleneck is gone.

This is the same difficulty you met in the kernel, and it is the one idea worth remembering: a duration tells you where the time went, never what to change. A long initcall tells you an initcall blocked, and finding what it blocked on takes a trace. blame tells you a unit was slow, and finding what made it slow takes critical-chain. One difficulty, two phases.

Tracing the period that has no log yet

There is a stretch early in the kernel where you would like ftrace data and no user space exists yet to switch it on. Boot-time tracing solves that. Through bootconfig you can enable trace events, filters, histograms, and kprobe events straight from the boot command line, so tracing is running while devices initialize. See Documentation/admin-guide/bootconfig.rst for the file format and Documentation/trace/boottime-trace.rst for the ftrace.* and kernel.* keys.

This also gives a cleaner source than dmesg for initcall timing. The initcall_start and initcall_finish tracepoints are the same ones initcall_debug registers against, so reading them through ftrace gives you timestamped events in the ring buffer rather than formatted log lines. That is easier to process, and it does not add console output time to the boot you are measuring.

A worked example

The numbers below are constructed rather than taken from one particular project, but the arithmetic is what makes the point.

Where the measurement started

An industrial gateway on an i.MX8M Plus, booting from eMMC, with a requirement of four seconds from power-on to the first camera frame. It measured 11.0 seconds, and measuring the bootloader had already removed 1.6 seconds of unnecessary USB and Ethernet initialization from U-Boot.

That leaves 5.4 seconds to find, all of it in the two phases this article measures. The kernel configuration work the team had originally planned is still untouched, and the 9.8 MB kernel image is still shipping.

What the timelines show

User space is the larger of the two, so start there.

raghu@techveda.org:~$ systemd-analyze critical-chain
multi-user.target @4.482s
└─camera-gateway.service @4.309s +173ms
  └─network-online.target @4.301s
    └─systemd-networkd-wait-online.service @0.874s +3.427s
      └─systemd-networkd.service @0.821s +53ms
        └─dbus.socket @0.814s

The application takes 173 milliseconds to start. It waited 3.4 seconds to be allowed to. Note what blame would have shown: systemd-networkd-wait-online.service at the top, which is correct, with no indication that the change belongs in camera-gateway.service rather than in the networking unit. The chain shows the dependency. The ranking does not.

The kernel’s 3.2 seconds sorts like this:

raghu@techveda.org:~$ dmesg | grep 'initcall .* returned' |
    awk '{print $(NF-1), $0}' | sort -rn | cut -d' ' -f2- | head -4
[    2.418836] initcall ov5640_driver_init+0x0/0x28 returned 0 after 1298204 usecs
[    1.087402] initcall imx_vpu_init+0x0/0x40 returned 0 after 411903 usecs
[    0.914255] initcall imx_pcie_init+0x0/0x2c returned 0 after 187330 usecs
[    1.502118] initcall regulator_init_complete+0x0/0x30 returned 0 after 42118 usecs

Two entries account for 1.7 of the 3.2 seconds, and neither is executing code. Function graph tracing on ov5640_driver_init puts almost all of its 1.3 seconds inside a single regulator enable. The device tree declared regulator-enable-ramp-delay = <1300000> for the camera sensor supply. That property is in microseconds, so the value is 1.3 seconds. It had been copied from a reference design and never checked against the regulator actually fitted, which settles in about 25 milliseconds. The second entry is the VPU driver calling request_firmware() during its initcall and reading the blob off eMMC, for firmware this product does not need until well after the first frame is on the display.

What changes, and what it costs

Three changes, none of them in the application’s own startup code.

• Removing network-online.target from camera-gateway.service‘s After= list, and letting the application handle the network being absent, removes 3.4 seconds. User space drops from 4.5 to 1.1 seconds.
• Correcting the ramp delay to the fitted regulator’s datasheet figure removes 1.3 seconds.
• Building the VPU driver as a module and loading it after the display is up removes a further 0.4 seconds. The kernel drops from 3.2 to 1.5 seconds.

That gives 0.4 + 1.3 + 1.5 + 1.1, or 4.3 seconds, against a requirement of 4.0. The last 0.3 seconds is not an optimization. It is the console. Every measurement so far was taken with ignore_loglevel and a verbose boot, because that is the instrumented configuration. Re-measured with quiet, the production image reaches the first camera frame in 4.0 seconds. The instrumented number and the production number are different numbers, and only one of them is the number the product has.

None of this is free. The application had to be modified to start without a network and connect later, which is a real code change needing tests against a network that never arrives as well as one that arrives late. The device tree correction is carried as a patch on the vendor BSP, so it needs rebasing on every vendor update and rechecking on every hardware revision. Moving the VPU driver to a module gives the video encode path a load step that can fail where it previously could not.

And meeting a four-second requirement at exactly 4.0 seconds leaves no headroom. A slower eMMC part in a later production run, or one more service on the boot path, puts the product back outside its requirement with no warning. A boot time measurement is worth repeating in CI, not only at the end of a project.

What the measurement usually tells you to do

Once you have the numbers, the options sort into three groups. Which group you end up in depends entirely on what you measured, which is why this sits at the end of the article rather than the start.

Almost always available

• Remove dependencies, not services. A unit waiting on network-online.target that does not need the network is the single most common user-space finding.
• Fix what a blocked initcall was waiting for. A ramp delay copied from a reference design, a firmware file on slow storage, or a bus scan hunting for a device that is not fitted are all removable once you know which one it is.
• Match the compressor to your storage speed. The in-tree Kconfig help states the tradeoff: LZ4 decompresses faster than LZO at roughly 8 percent larger size, and ZSTD compresses better than gzip while decompressing at around LZO speed. On fast storage with a slow CPU, decompression dominates and the faster algorithm wins; on slow storage the read dominates and the smaller image wins. Test at least two on your board.
• Turn off the console for the production measurement. Not as a fix, but so your reported number is the one the product will have. A console at 115200 baud with 8N1 framing carries ten bits per character, about 11.5 kilobytes per second, and a verbose boot can spend hundreds of milliseconds printing.

Needs a design decision

• Built-in versus modular drivers. Building drivers in removes module load and udev work but grows the image, and therefore the load and decompress time. Moving one out, as the VPU example does, takes it off the boot path but adds a load step that can fail. Only a measurement tells you which way it goes on your board.
• Read-only root filesystem format. EROFS, in mainline since Linux 5.4, uses fixed-size output compression: variable-sized input extents are compressed into physical clusters, with logical clusters fixed at block size, typically 4 KiB. Physical clusters were 4 KiB only until the big-pcluster feature in Linux 5.13 allowed multiples, tunable with mkfs.erofs -C. SquashFS defaults to 128 KiB blocks and can be configured up to 1 MiB. For the small random reads early boot does, the smaller decompression unit means less wasted read and decode. If you already run a read-only rootfs — and if you use dm-verity you do — this is worth measuring.
• Splitting the application’s startup. Letting an application start before its dependencies are ready is often the largest single user-space saving, and it is a genuine code change with genuine failure modes rather than a configuration edit.

Not worth making

• Removing kernel configuration options for their own sake, without a measurement showing that image size or a specific initcall is on the critical path. This is the most common wasted effort in boot time projects.
• Optimizing an initcall that is blocked. Check /sys/kernel/debug/devices_deferred before touching driver code.
• Optimizing a service that is not on the critical chain. Check critical-chain before touching a unit file.
• Removing the serial console early in the project. You lose your measurement instrument to save time you have not yet proved you need.

The measurement sequence

The whole thing for these two phases, in order. On a board you already have running it takes well under an hour.

1. Boot with initcall_debug ignore_loglevel printk.time=1.
2. Sort dmesg by the duration field with the awk pipeline above. Note the top five.
3. Run bootgraph.pl and look at the gaps, not only the bars.
4. Trace the worst entry with function graph tracing to find what it blocked on. The duration alone will not tell you.
5. Confirm with initcall_blacklist= before you change any code.
6. Read /sys/kernel/debug/devices_deferred separately. It answers a different question: which devices never probed at all.
7. Run systemd-analyze time for the kernel, initrd, and userspace split.
8. Run systemd-analyze critical-chain and follow it down to the first unit with a large + value. That is your target.
9. Run systemd-analyze blame only now, to see what becomes the bottleneck after this one is fixed.
10. Repeat with quiet to get the production number rather than the instrumented one.

If your requirement is written from power-on rather than kernel entry, this covers only two of the four phases. The bootloader and boot ROM are in the article on the four boot phases, and they need instrumenting separately.

What this means in practice

Sort initcall_debug output by duration, but do not believe any single number until you have checked /sys/kernel/debug/devices_deferred, because a blocked initcall and a busy initcall are indistinguishable in the log. In user space, start with critical-chain, then read blame to see which units will block you next.

The measurement usually points somewhere other than where the team was already working, and the fix turns out to be smaller than the work that had been planned. The gateway above came down by seven seconds, and not one of the changes was in the code anybody had planned to optimize. Measuring first is not extra process. It is what stops two weeks of effort from producing 40 milliseconds.

Boot path work across the bootloader, kernel, and image is the core of our Embedded Linux BSP Development training, where the boot timeline is built on real hardware rather than described.

Frequently asked questions

My initcall_debug output has hundreds of sub-millisecond calls. How do I cut the noise?
The awk pipeline above already ranks by duration, so pipe it through head and ignore the tail. Anything under a millisecond is almost never worth reading. If the log itself is the problem, note that a verbose console is adding its own time to the boot you are measuring, so prefer the initcall tracepoints through ftrace: they land in the ring buffer without any console cost. Also check that the ring buffer did not wrap, which shows up as a dmesg that starts mid-boot; raise CONFIG_LOG_BUF_SHIFT or pass log_buf_len= if it did.

critical-chain points at a .device unit I cannot optimize. What does that mean?
It means systemd is waiting for a device to appear, and the delay is below systemd entirely. A dev-mmcblk0p2.device or similar at the head of your chain is a kernel or hardware question, not a unit-file question: the device is probing late, deferring, or waiting on a supplier. Go back to /sys/kernel/debug/devices_deferred and to the initcall ranking. This is the point where the two halves of this article meet, and it is a common place for people to get stuck editing unit files that cannot help them.

Can I switch initcall_debug on at runtime to time a module load?
Not on a kernel with CONFIG_TRACEPOINTS=y, despite the file at /sys/module/kernel/parameters/initcall_debug being mode 0644. The callbacks are registered once during start_kernel(), and only if the parameter was set on the command line, so writing to the file later has no effect on output. Enable the tracepoints instead: echo 1 > /sys/kernel/tracing/events/initcall/enable.

Is a device in devices_deferred the same as a slow initcall?
No, and the two are easy to confuse. A probe returning -EPROBE_DEFER returns at the point it finds the dependency missing, which is usually early and cheap, so it rarely accounts for a long initcall duration. What it produces is a device that has not probed yet. The cost turns up as a device that becomes available late, or not at all if deferred_probe_timeout= expires. That default comes from CONFIG_DRIVER_DEFERRED_PROBE_TIMEOUT: 0 without modules, 10 with them.

Why are the timestamps out of order when I sort by duration?
Because the timestamp is when the initcall finished, and initcalls run in level order — core, postcore, arch, subsys, fs, device, late — not in order of cost. A duration-sorted list will jump around in time, and that is expected. Use scripts/bootgraph.pl if you want the sequence rather than the ranking.

My requirement is measured from power-on. Is this enough?
No. The kernel and user space are two of four phases, and dmesg cannot see the other two. You also need the ROM and SPL interval, which takes a scope or a switched supply, and the bootloader, which U-Boot can time itself with CONFIG_BOOTSTAGE.

Further reading

• Embedded Linux boot time: the four phases and measuring the bootloader — joining all four phases onto one timeline, and U-Boot bootstage.
• The kernel’s boot parameter list — initcall_debug, initcall_blacklist=, deferred_probe_timeout=, printk.time=.
• Boot-time tracing and bootconfig — enabling ftrace from the boot command line.
• systemd-analyze manual — including the documented caveats on blame and critical-chain.
• EROFS documentation — fixed-size output compression and the big-pcluster feature.