Embedded Linux Boot Time: The Phase You Are Not Measuring

A board spends its boot time in four phases: ROM and SPL, U-Boot proper, the kernel, and user space. Each one has its own clock, and each clock starts at zero. That matters because the dmesg timestamp of 0.000000 is not power-on, so measuring the kernel alone tells you nothing about the two phases before it. This article walks through the four phases, shows how to put them on a single axis using a timestamped serial log, and covers measuring the bootloader with bootstage.

Every embedded Linux product eventually gets a boot time requirement. A backup camera has to show an image within two seconds. An industrial controller has to answer a fieldbus request before the master times out. A battery device has to finish booting before the wake budget is spent.

The requirement usually arrives late, and the response is usually the same. Someone opens dmesg, finds the slowest line, and starts working on it. Two weeks later the number has barely moved.

The engineer did not pick a bad target. The problem is that dmesg shows only one of the four phases a board goes through, and its clock starts at zero after two of the others have already finished. You can spend a long time optimizing something that was never the expensive part.

So this article is about measuring rather than tuning. Once you have a timeline that runs from power-on to the moment your application is ready, the decisions get easy and usually small. Without one, you are guessing.

Why boot time work usually goes wrong

Three things about the boot path make it hard to reason about until you instrument it.

Each phase has its own clock. The kernel log timestamp of 0.000000 is not power-on. It is the moment the kernel started running and printk timestamping became available. Everything the ROM, the SPL, and U-Boot did before that is not part of that number. On a board with slow storage and a large U-Boot, the time you cannot see is often longer than the entire kernel phase.

Time spent working and time spent waiting look identical. An initcall that takes 900 ms might be doing 900 ms of work. It might also be doing 5 ms of work and waiting 895 ms for a regulator, a clock, or a firmware file. The log line reads the same either way, and optimizing a driver that was blocked on something else saves you nothing.

In user space, a slow unit is not always a blocking unit. A service that takes 400 ms to start may not be on the critical path at all. If three other services start alongside it and the slowest takes 900 ms, removing your 400 ms service changes the ready time by zero.

Put those together and the result is a familiar pattern. A team spends two weeks removing kernel configuration options, ships an image 30 percent smaller, and finds that boot time moved by 40 ms. The real cost was a 1.2 second driver initialization sequence in U-Boot that nobody had measured.

The four phases, and the handoffs between them

Agree on where each phase starts and ends before you instrument anything. The handoffs between them are where measurements get lost.

Phase	Clock starts at	Measured with
1. ROM and SPL	power-on	scope or switched supply, no console output
2. U-Boot proper	U-Boot timer init	bootstage
3. Kernel	kernel entry	initcall_debug
4. User space	init exec	systemd-analyze

One external clock on the serial line joins phases 2, 3 and 4. Phase 1 needs hardware.

Phase 1: ROM and SPL

The SoC boot ROM runs from mask ROM, reads a boot mode strap or fuse, and loads a small first-stage image into on-chip SRAM. That image is the SPL, or TF-A BL2 on many Arm platforms. The SPL brings up DRAM, which is the reason it exists. Nothing bigger can run until the DDR controller is trained and calibrated.

On most platforms this phase prints almost nothing, and two things dominate its cost: how fast the ROM reads from the boot medium, and how long DDR training takes. On some DDR4 and LPDDR4 platforms training runs to several hundred milliseconds. A few vendors let you save the trained parameters so later boots skip the full sequence, which is worth asking about early.

Phase 2: U-Boot proper

U-Boot relocates itself to DRAM, initializes drivers, reads the environment, loads the kernel, device tree, and initramfs, verifies signatures if you use verified boot, and jumps to the kernel.

This is where unmeasured time builds up most often, because U-Boot sets up devices the kernel will set up again a second later. The duplication is not automatic: under the U-Boot driver model, a device that is bound but never probed costs very little. But any subsystem your boot path actually touches and your product does not need is time spent twice.

Phase 3: kernel

The kernel decompresses itself, sets up memory management and the scheduler, runs initcalls in level order, mounts the root filesystem, and executes the init process. Almost all of the variable cost is in initcalls and in waiting for the root device to appear. The kernel's own instrumentation is the initcall_debug boot parameter, which logs every initcall with a duration.

Phase 4: user space

The init system starts services until it reaches the unit or target your application depends on. On most product images that is systemd, and the number worth having is systemd-analyze critical-chain, not the total.

Notice what all four have in common. The requirement you were given is measured from power-on, and every tool in the standard set measures from the start of its own phase. Joining them up is a separate job, and it is the one most teams skip.

Building one timeline across all four phases

The problem: four clocks, no shared zero

U-Boot's bootstage timestamps start when U-Boot's timer is available. The kernel's printk timestamps start when the kernel starts. systemd-analyze reports a kernel time, an initrd time, and a userspace time, but its idea of "kernel time" begins where the bootloader handed over. None of these share an origin with the moment power was applied or the reset line was released.

Adding the phase totals together gets you close, but it leaves out the ROM time and every handoff gap along the way. Those gaps are exactly where unaccounted time usually is.

The fix: an external clock on the serial line

What works is timestamping the serial console from outside the board, so one clock covers everything the board prints, from the first SPL character to your application's ready message.

grabserial does this. It reads the serial port, adds a timestamp to each line, and can reset its base time when a line matches a pattern, so you can anchor zero on a marker you choose.

$ grabserial -v -d /dev/ttyUSB0 -b 115200 -e 30 -t -m "U-Boot SPL"

Reset the board with power rather than a warm reset, because a warm reset can skip ROM work that a cold boot performs. Capture the whole log to a file. That file becomes your timeline, and you read every later measurement against it.

Two settings make the log easier to work with:

• Build the kernel with CONFIG_PRINTK_TIME=y, or pass printk.time=1, so kernel lines carry their own timestamps as well. The kernel records the timestamp internally either way and exports it through /dev/kmsg; the option controls whether it appears in console output.
• The console itself costs time. A serial console at 115200 baud with 8N1 framing carries ten bits per character, so it moves about 11.5 kilobytes per second, and a verbose boot can spend hundreds of milliseconds printing. Measure with the console on to find your targets, then measure again with quiet to see the production number. Do not confuse the two.

What the serial line cannot show you

This method has one limit, and it is worth being clear about it. The serial timeline begins at the first character the board prints, which on most platforms is the first SPL message. Everything before that is invisible: the boot ROM reading the SPL off eMMC, SD, or SPI-NOR prints nothing, so none of it reaches the log.

Measure that interval separately, with hardware. Trigger the boot from something you can observe — a switched supply, a controlled reset line, or a scope probe on the reset signal and the serial TX line. What you get is the ROM read plus the SPL load, and on a slow boot medium that interval can be large.

You only have to measure it once. It rarely changes between software builds, so take it per board and per boot medium, write it down, and record it with the four phase totals.

Measuring the bootloader with bootstage

U-Boot can time its own boot, and most people never turn it on. Enable CONFIG_BOOTSTAGE in boot/Kconfig and it records timing marks at known points. There are two ways to read them back:

• CONFIG_BOOTSTAGE_REPORT prints a timing summary automatically before U-Boot hands off to the OS.
• CONFIG_CMD_BOOTSTAGE adds the bootstage command, so you can run bootstage report from the prompt. This is a separate symbol from the report option, and it depends on BOOTSTAGE.

The report is a table of marks in microseconds:

=> bootstage report
Timer summary in microseconds:
       Mark    Elapsed  Stage
          0          0  reset
    213,405    213,405  board_init_f
    418,772    205,367  board_init_r
    724,190    305,418  main_loop
    944,318    220,128  bootm_start
  1,204,551    260,233  start_kernel

Accumulated time:
                 41,220  dm_spl
                162,663  dm_r

The Elapsed column is the one to read, and it is easy to read it backwards. Elapsed is the time between the previous mark and this one, not the time spent inside the stage the row is named after. The 305,418 microseconds on the main_loop row is therefore the interval from board_init_r to main_loop, which is where U-Boot initializes drivers and reads its environment.

Read that way, the intervals here rank as:

1. 305 ms, board_init_r to main_loop — driver initialization and environment work in U-Boot proper.
2. 260 ms, bootm_start to start_kernel — image load, signature verification, and kernel decompression.
3. 220 ms, main_loop to bootm_start — environment processing and boot command parsing.
4. 213 ms, reset to board_init_f — SPL work and relocation, as U-Boot's own timer sees it.
5. 205 ms, board_init_f to board_init_r — early init and relocation into DRAM.

The Accumulated section at the bottom narrows the largest item further. Of that 305 ms interval, 162,663 microseconds went on driver model probes in U-Boot proper (dm_r), against 41,220 in the SPL (dm_spl). If you need more detail than that, bootstage_mark_name() lets you add marks of your own around whichever subsystem you suspect, then rebuild.

Reducing bootloader time

Once you know where the bootloader spends its time, there are two options inside U-Boot itself and a third that belongs to the phase before it. None of them is tuning. All are decisions someone has to sign off on.

Reduce U-Boot's driver set. Anything U-Boot probes and never uses is time spent twice, because the kernel probes it again a moment later. Network, USB, and display are the usual candidates on a product that boots from local storage. They are almost always there for a factory or recovery path, which means the answer is usually two build configurations rather than one stripped-down one.

Falcon mode. CONFIG_SPL_OS_BOOT lets the SPL load and start the kernel directly, skipping U-Boot proper altogether. That removes the whole of phase 2, and on some designs it is the largest single saving available to you. It also costs you the U-Boot command line, the environment, and the normal update and recovery path, so most products keep a way back into full U-Boot. doc/develop/falcon.rst in the U-Boot tree describes how it works.

Saved DDR training parameters. This one belongs to phase 1 and depends on your SoC: some vendors let you save the trained parameters so later boots skip the full calibration. It reduces time in the phase that is hardest to instrument, which is why it is worth raising with your vendor early rather than late.

One warning if your product uses verified boot. All three of these affect signing. Two U-Boot configurations means two signing paths to maintain through the release process, and Falcon mode changes which component verifies the kernel.

A worked example

The numbers below are constructed rather than taken from one particular project. This is a common form of the problem, and the arithmetic is what makes the argument concrete, so it is worth walking through.

What the team expected

An industrial gateway on an i.MX8M Plus, booting from eMMC. The requirement is four seconds from power-on to the first camera frame on the display. Measured boot time is 11.0 seconds.

The kernel image is 9.8 MB, which feels large to everyone who looks at it. So the plan is two weeks of kernel configuration work, plus an evaluation of whether moving the image from Yocto to Buildroot would help. Nobody has measured anything except the total.

What the timeline shows

An afternoon of measurement produces this split:

Phase	Time
ROM and SPL, up to U-Boot proper (scope plus serial log)	0.4 s
U-Boot proper (bootstage report)	2.9 s
Kernel (dmesg)	3.2 s
User space (systemd-analyze)	4.5 s
Total	11.0 s

The first thing to notice is that 3.3 seconds of the 11 happen before the kernel starts, and none of it appears in dmesg. The team had been reading a log that begins after almost a third of the boot is already over.

Inside U-Boot, bootstage report puts 1.6 of the 2.9 seconds in USB and Ethernet initialization, and the Accumulated dm_r figure confirms most of it is driver model probing. Both subsystems exist for a TFTP recovery path. The boot script calls usb start and brings the interface up unconditionally, so the cost is paid on every boot, including the deployed units that never use that path.

What changes

Splitting U-Boot into a factory configuration with USB and Ethernet, and a production configuration without them, removes 1.6 seconds. That is an afternoon of work against the two weeks that had been planned, and the kernel configuration is never touched. The 9.8 MB image ships.

It is worth being honest about what this does not do. Removing 1.6 seconds from 11.0 leaves 9.4, against a requirement of four. The bootloader was not the whole problem, and finding the rest means measuring the kernel and user space, which is a separate investigation. What the afternoon established is that two weeks of kernel configuration work would have produced very little.

What it costs

Two U-Boot configurations now have to be maintained. Because the product uses verified boot, that also means two signing paths and two sets of keys to keep track of through the release process. There is a further risk that is easy to miss: the factory configuration and the production configuration can diverge, and a fault introduced in one may only appear on the production line, which is the worst place to find it. None of that is free. It is still smaller than two weeks spent on the wrong phase.

A bootloader measurement checklist

Here is the whole sequence for the first two phases, in order. On a board you already have running it takes about an hour.

1. Measure the interval from reset release to the first serial character once, with a scope or a controlled supply. This is your ROM and SPL-load cost, and it will not appear in any software log.
2. Connect a host to the serial console and start grabserial with an anchor pattern on the first SPL message.
3. Power cycle the board. Do not use a warm reset. Capture the full log to a file.
4. Enable CONFIG_BOOTSTAGE and CONFIG_CMD_BOOTSTAGE in U-Boot, boot, and run bootstage report.
5. Record the Elapsed column, reading each value as the interval before that mark rather than time spent inside the named stage.
6. Check the Accumulated section for dm_spl and dm_r. Those totals tell you how much of the bootloader's time is driver model probing.
7. Compare U-Boot's own total against the same interval in your grabserial log. If they disagree, the difference is a handoff gap, and you want to know where it is.
8. Repeat with quiet on the kernel command line to get the production number rather than the instrumented one.

What this means in practice

For the first day, treat boot time as a measurement problem. It becomes an engineering problem after that, and not before. Get an external clock onto the serial line so all four phases sit on one axis. Measure the pre-console ROM interval with hardware, because no amount of software will show it to you. And instrument the bootloader before you touch the kernel, because the phase you cannot see in dmesg is often the expensive one.

If the bootloader does turn out to account for most of your budget, the options above are design decisions with real costs attached, and you want to base them on a measurement rather than a guess. If it does not, the afternoon was still worth spending: you have ruled out two whole phases, and whatever remains is in the kernel or user space. That is a much smaller place to look.

Key takeaways

• Boot time spans four phases with four independent clocks. dmesg timestamps start at kernel entry, not at power-on, so kernel-only measurement misses everything before it.
• Join the phases with an external timestamp on the serial console. grabserial with an anchor pattern is the standard method, and a cold power cycle is required.
• The interval before the first serial character cannot be measured in software. Use a scope or a controlled supply, once per board and boot medium.
• U-Boot has built-in timing: CONFIG_BOOTSTAGE for the marks, CONFIG_BOOTSTAGE_REPORT to print automatically, CONFIG_CMD_BOOTSTAGE for the bootstage report command.
• Elapsed is the interval before each mark, not the time spent inside the named stage. Reading it the other way inverts your conclusions.
• The Accumulated section separates driver model probe time in the SPL (dm_spl) from U-Boot proper (dm_r).
• The structural bootloader options are a reduced driver set, Falcon mode, and saved DDR training parameters. All trade against update, recovery, or vendor dependency, and all interact with verified boot signing.
• The console costs real time: 115200 baud with 8N1 framing is about 11.5 kilobytes per second. Measure with it on to find targets, and again with quiet to report the production number.

Frequently asked questions

Why does dmesg show a boot time much shorter than what I measure with a stopwatch?

Because the kernel's printk timestamp starts at zero when the kernel starts running, not at power-on. Everything the boot ROM, the SPL, and U-Boot did before that point is outside the number. On boards with slow storage or long DDR training, that interval can exceed the whole kernel phase. To see it, timestamp the serial console from outside the board with a tool such as grabserial, enable CONFIG_BOOTSTAGE in U-Boot, and measure the pre-console ROM interval with a scope or a controlled supply.

What exactly does the Elapsed column in bootstage report mean?

It is the time between the previous mark and that mark, not the time spent inside the stage the row is named after. So an Elapsed value on the start_kernel row is the interval from bootm_start to start_kernel. Reading it as "time spent in start_kernel" will point you at the wrong stage. The Accumulated section at the bottom is different: those values are totals for driver model probing in the SPL (dm_spl) and in U-Boot proper (dm_r).

How do I measure the boot ROM, when it prints nothing?

You cannot do it in software, because there is no log until the SPL starts printing. Use hardware: a switched supply or a controlled reset line, and a scope probe on the reset signal and the serial TX line. The interval from reset release to the first serial character is the ROM read plus the SPL load. It does not usually change between software builds, so measure it once per board and per boot medium and carry it as a fixed number.

Does turning off the serial console actually change boot time?

Yes, and usually by more than people expect. A console at 115200 baud with 8N1 framing carries about 11.5 kilobytes per second, so a verbose boot can spend hundreds of milliseconds doing nothing but printing. Keep it on while you are looking for targets, since it is your measurement instrument. Then take a second measurement with quiet on the command line, and report that one, because it is the number the product will actually have.

Further reading

• U-Boot: Falcon mode — booting the kernel directly from the SPL.
• The kernel's boot parameter list — including printk.time= and quiet.
• grabserial — Tim Bird's serial timestamping tool.