Three minutes to boot, two of them in Python imports

Our boards took about three minutes from power-on to accepting their first command. The kernel was finished after two and a half seconds. The rest was ours: systemd waiting two minutes for a network cable nobody had plugged in, and four Python services spending between half a minute and well over a minute each just importing themselves.

When we started, we looked for a write-up of how to profile a boot like this and didn't find one. Plenty exists for kernel boot time, and plenty for Python startup on a laptop. Nothing covered the space in between: a small ARM board, a Yocto image, systemd, and a handful of Python daemons that all start at once and get in each other's way.

This is the method we ended up with, in the order we'd use it again. The device is a quad Cortex-A55 board (Amlogic S905D3) with a six-core A311D board as a second reference. The tools are the ones a minimal image already has, plus a few lines of awk.

#Decide what "booted" means

"Boot time" is meaningless until you pick the moment that counts. Ours is the first moment the device can do its job: the log line where the main service subscribes to its command topic. A second milestone is the moment the on-device screen first shows network status, because that's what a person standing next to the device sees.

Every milestone is a log line, so each number is the line's timestamp minus the boot time the kernel reports in /proc/stat:

BTIME = next(int(l.split()[1]) for l in open("/proc/stat") if l.startswith("btime"))

def since_boot(wall_clock_ts: float) -> float:
    return wall_clock_ts - BTIME

Reboot cold with systemctl reboot, wait for the milestones, record them. Single boots were consistent enough to see effects of a few seconds. When two numbers were close, we booted again.

#The clock moves under you

The first numbers we collected were wrong by fourteen seconds, and nothing looked off.

A board without a real-time clock boots with a stale wall clock. systemd-timesyncd corrects it about 37 seconds in, in one jump of 14 seconds on our board (10.5 seconds on the other). btime is derived from the wall clock, so it jumps too. A log line written before the step, converted with the btime read after it, comes out 14 seconds late.

Two fixes, and you need both:

• Read btime after the boot has settled, and make sure every milestone you convert with it was logged after the step.
• For anything logged before the step, use the journal's monotonic clock, which doesn't move:

journalctl -b -o short-monotonic | grep -E "Initial clock synchronization|spawned"

#Layer one: the bootloader and kernel

A serial console with the host stamping each line gives you the bootloader's timeline for free. Ours spent 5.8 seconds in U-Boot: 1.8 scanning a USB bus, 1 sitting in bootdelay, and the rest loading and unpacking the kernel. The kernel itself took 2.3 seconds.

Setting bootdelay=0 and skipping the USB scan saved about three seconds, and we didn't ship it. Our updates replace the root filesystem, not the bootloader or its environment, so the change would only ever reach freshly flashed devices. Before you tune a layer, check that your update path can actually reach it.

#Layer two: systemd

Two commands find nearly everything at this layer:

Startup finished in 2.342s (kernel) + 2min 6.837s (userspace) = 2min 9.180s
2min 175ms systemd-networkd-wait-online.service
   18.038s plymouth-wait-for-animation.service
   15.058s plymouth-quit-wait.service

systemd-analyze critical-chain then tells you which of those actually delays the thing you care about. Here, systemd-networkd-wait-online waited its full two minutes for an Ethernet cable that wasn't connected, and it held network-online.target, which the update client and telemetry waited on. The device doesn't even use systemd-networkd: NetworkManager runs the network.

It had already been switched off, twice, and neither attempt had worked:

• A preset file said disable systemd-networkd-wait-online without the .service suffix. The upstream preset file is read first, and the first match wins, so ours never applied.
• IMAGE_INSTALL:remove = "systemd-networkd" did nothing, because networkd is a build option of the systemd recipe, not a package.

Removing it from systemd's PACKAGECONFIG took userspace from 2 minutes 6.8 seconds to 12.4. The lesson is about where you check: look in the built image (systemctl is-enabled, systemd-analyze), not in the recipe that was supposed to do it.

#Layer three: Python imports

This is where the time was. Start by timing a bare import of each service's entry point, on the device, while the other services run as they would at boot:

/usr/bin/time -f "%e s" python3 -c "import service.app"

Then find out where it goes. python -X importtime prints one line per module with its own time ("self") and its time including everything it imported ("cumulative"). Sorting by self time finds the expensive modules:

python3 -X importtime -c "import service.app" 2> imp.txt
awk -F'|' '/import time:/ {gsub(/import time: */, "", $1); print $1+0, $3}' imp.txt | sort -rn | head -20

One trap before reading the output. The same module took 18.4 seconds in one run and 8.9 in a later one, on the same board. Imports compete for four cores with every other service starting at the same time. Compare runs taken under the same conditions, and trust the change between two runs more than any single absolute number.

We found three kinds of problem, and they're probably the three you'll find.

#A library doing work at import time

cProfile on the import itself, sorted by cumulative time, pointed at one call stack again and again:

cProfile.run("import service.app", "imp.prof")
pstats.Stats("imp.prof").sort_stats("cumulative").print_stats(r"build_call_model|create_model", 20)

Our dependency-injection library, fast_depends, builds a Pydantic model for every decorated function's signature so it can validate and convert arguments. Fifty-four decorators, applied recursively, built about 3,350 models before the service had done anything.

We turned casting off and left defer_build alone. Deferring only moves the work to the first time each command runs, and it saved less.

Casting turned out to be doing a real job, and that's the part worth remembering. One transport delivered command payloads as plain dicts, and the injection layer had been converting them into typed objects without anyone noticing. With casting off, two commands failed straight away with 'dict' object has no attribute 'enabled_only'. The fix was to parse each payload into its declared type explicitly, at the point where commands enter the service. When you remove a convenience, find out what it was doing for you.

#Something heavy imported by accident

importtime prints a module's children before the module itself, so you can walk upward from any expensive line to find who asked for it. One walk ended somewhere surprising.

The MQTT supervisor needed one small type to build its last-will message. The module that type lived in also imported the schemas for a cloud image-generation workflow, which nothing on the device ever uses. Moving the type into its own module took the main service's import from 46.8 seconds to 34.2.

#Packages that import everything on first touch

Each of our schema packages imported all of its submodules in __init__.py, so asking for one class loaded dozens of modules. PEP 562 lets a package define __getattr__ and load submodules only when they're first touched. A .pyi stub keeps type checkers and editors working.

The last row is the reason to measure every service after every change. Lazy loading changed the order in which modules loaded. For the main service, some cost simply moved somewhere else, and one module got four times slower depending on what was already in memory. The change also exposed an import cycle that the eager order had been hiding.

#Layer four: after the imports, before ready

Some time hides between "imports done" and "ready", and importtime can't see it. Our image has no py-spy, so we sampled the main thread's stack from inside the process. A temporary sitecustomize.py that runs only for one service does it:

import os, sys, threading, time, traceback

if os.path.basename(sys.argv[0]) == "device-service":
    main = threading.main_thread()

    def sample():
        with open("/tmp/stack-samples.txt", "w") as out:
            for _ in range(150):
                time.sleep(1)
                out.write("".join(traceback.format_stack(sys._current_frames()[main.ident])) + "\n---\n")

    threading.Thread(target=sample, daemon=True).start()

Every sample in a 27-second gap after the MQTT connection was the same model building as before, this time in a dependency resolver that wrapped providers with the casting version of the injector. Fixing it took that gap from 27.6 seconds to 2.9.

The renderer had a different problem, and it's an easy one to miss.

The renderer starts its window in a child process with multiprocessing in forkserver mode, and asks the fork server to preload the app so that children start warm. In Python 3.12 that preload silently does nothing when the program was started from a console-script entry point. The fork server only preloads __main__ when it's given a main path, and for a console script it never is. So every child re-imported the whole app: 27 seconds, every time the display resolution changed.

The fork server's command line in /proc shows what it actually preloaded, and its memory map shows whether the app is loaded. Here, neither showed the app. The fix is a small launcher that names the module explicitly and starts the fork server before the parent begins its own imports, so the two run on separate cores:

import multiprocessing
import multiprocessing.forkserver

def main():
    multiprocessing.set_start_method("forkserver", force=True)
    multiprocessing.set_forkserver_preload(["renderer.app"])
    multiprocessing.forkserver.ensure_running()
    from renderer.app import app
    app()

Changing resolution went from 29.5 seconds to 2.5.

The last thing in this layer was services waiting for each other. The display reconnected to the main service with exponential backoff capped at 30 seconds, so at boot it was usually asleep when the socket appeared. Refusing a connection on a local Unix socket costs nothing, so the cap went to one second, and the display now connects 0.4 seconds after the socket is up.

#Layer five: what it costs while idle

A fast boot followed by a busy idle still feels slow. Measure idle properly first: ps reports CPU time divided by time since the process started, so right after boot it showed the main service at 48 percent, all of it imports. Over a 30-second window, after three minutes of uptime, it was 3.5 percent. Take deltas of utime + stime from /proc/<pid>/stat instead.

Three findings are worth checking on any board:

• The CPU governor. schedutil changed frequency 150 to 370 times a second at idle, according to cpufreq/policy*/stats/total_trans, and its kernel thread used up to a fifth of a core. On the six-core board, the performance governor took idle from 8 to 2 percent for 2.6 °C, far below the 85 °C trip point.
• A cgroup memory limit below the working set. The telemetry collector had MemoryHigh=48M against a working set of about 70 MB. The kernel kept reclaiming its pages, including its own 42 MB binary. The collector then read the binary back from compressed storage: 450 page faults a second, 6.6 MB/s of disk reads, and a busy btrfs-endio worker. memory.events in the unit's cgroup showed about 3,000 high events since boot. Raising the limit took the collector from 6.7 to 1.6 percent CPU.
• Things left on. A continuous profiler enabled by default cost 1.2 percent of CPU and 85 MB of memory. A UI framework redrawing a small status panel at 60 frames a second used 5 percent; at 15, which is plenty for that panel, it uses 1.7.

#What we didn't do

Upgrade to Python 3.15 for lazy imports. PEP 810 makes lazy imports a language feature, and it's tempting. But lazy imports defer loading, and our cost was work done at load time, which only moves. The lazy-__init__ results above show it can move somewhere worse. On top of that, a new Python on a Yocto release means new recipes and rebuilding every native extension.

Rewrite the hot path in Rust. The per-frame work already runs on the GPU, and the playback pipeline dropped no frames late. Profiling put the saving from a Rust element at about one percent of a core.

Defer every Pydantic model. It saved less than removing the work, and the first command of each type would have paid the difference.

#The result

These are the quad-core board running the image we ship, which keeps the 18-second splash on purpose. With every change applied by hand, including a shorter splash and the bootloader settings, it reached 68.6 seconds. The six-core board went from 95.9 to 51.1 seconds.

#The method, short

1. Define "booted" as a log line a user would recognise, and convert timestamps with a btime read after the clock settles.
2. Get the timeline from the serial console and systemd-analyze blame and critical-chain.
3. Remove waits before you optimise work. A two-minute timeout beats every import trick combined.
4. Time each service's import on the device, under boot conditions, and sort -X importtime by self time.
5. Walk up the import tree to find who asked for each expensive module.
6. cProfile the import to catch libraries that work at import time, and sample stacks to catch what happens after.
7. Check that every child process actually inherits what you think you preloaded.
8. Change one thing, then measure every service. The one you changed is rarely the only one that moves.
9. Measure idle in windows, after the boot has settled.

"You can't tell where a program is going to spend its time. Bottlenecks occur in surprising places, so don't try to second guess and put in a speed hack until you've proven that's where the bottleneck is."

Rob Pike, rule 1 of his five rules of programming (1989)