Measuring the boot time

Overview of boot time measurement
Tools to measure boot time (e.g., systemd-analyze, dmesg, bootchart)
How to track boot events and milestones

Measuring boot time on redpesk OS involves capturing how long it takes for the system to transition from power-on or bootloader execution to a fully operational state. Here’s a step-by-step guide:

Define the start and end points

Start Point: Power-on or the bootloader’s first activity
End Point: When a specific service or application is ready. The appearance of a login prompt or GUI. A signal sent from the system (e.g. specific systemd service like multi-user.target or a network connection established)

Some methods to measure boot time

Using Bootloader (e.g., U-Boot) Timestamps Enable verbose output in the bootloader. Add timestamps to bootloader messages to measure the time spent in firmware and bootloader stages.
```
  CONFIG_TIMESTAMP=y
```
Using Kernel Boot Logs Enable Kernel Timestamps: Pass time or initcall_debug as a boot parameter in the kernel command line.
```
loglevel=8 time initcall_debug
```
- loglevel=8: Ensures all messages are displayed, including debug messages.
- time: Displays timestamps for each log entry relative to the boot start.
- initcall_debug: This shows the time taken by each kernel subsystem or driver initialization function. to the bootloader configuration.
Analyze Dmesg Logs: Run dmesg after boot to see timestamps for kernel initialization. Subtract the initial timestamp from the last timestamp to calculate boot time.
Using systemd-analyze (For Systemd-based Systems) Install and run systemd-analyze
systemd-analyze: This displays the total boot time split into kernel, initramfs, and user space. To generate a svg file:
```
systemd-analyze
```
```
 systemd-analyze plot > /tmp/bootup.svg
```
To see the time taken by each service:
```
systemd-analyze blame
```
For a detailed breakdown:
```
  systemd-analyze critical-chain
```
- systemd-analyze
Using UART or Serial Console Logs Connect to the device’s serial console using a tool like picocom or putty. Capture the boot log and note the timestamps. Measure from the first log line (e.g., bootloader starting) to the desired milestone.
Using GPIO and Oscilloscope/Logic Analyzer Configure a GPIO pin to toggle high when the kernel starts and low when the application is ready. Measure the time difference between the toggles using an oscilloscope or logic analyzer. This method is especially useful for real-time, hardware-accurate boot time measurements.
Measure Time to User Space To measure the time taken to reach user space, note the timestamp of the following message in dmesg:
```
  [    X.XXXXX] Run /sbin/init as init process
```
Subtract the kernel start time (typically [0.000000]) from the timestamp of this message.
Bootchart analysis Install systemd-bootchart. Enable bootchart by adding init=/usr/lib/systemd/systemd-bootchart to the kernel command line. Boot the system and review the generated chart in /var/log/bootchart/.

WARNING:

For systemd-bootchart, several proc debug interfaces are required in the kernel config: CONFIG_SCHEDSTATS below is optional, for additional info: CONFIG_SCHED_DEBUG

Optimize and Re-Test After measuring, identify bottlenecks using the detailed logs (e.g., long-running services, slow hardware initialization). Apply optimizations and repeat measurements to evaluate improvements.

By combining these methods, you can pinpoint where time is spent during boot and systematically reduce it.

Using bootloader timestamps

Enable timestamp logging in U-Boot

Configure U-Boot to enable timestamps: Open the U-Boot configuration file, typically located in the source tree as .config. Enable the CONFIG_BOOTSTAGE option:

    CONFIG_BOOTSTAGE=y

or with menuconfig

    make menuconfig
    Boot options  ---> Boot timing  ---> [ ] Boot timing and reporting 

This activates the bootstage feature in U-Boot, which records timestamps during the boot process.

And now rebuild U-Boot. Flash the compiled U-Boot binary to your device. Ensure that you have the correct flashing tool and binary format for your hardware.

Modify U-Boot to add explicit timestamp logging

If timestamps are not available natively or additional granularity is needed, you can modify the source code:

Edit the common/board_r.c File:

Add timestamp logging at key points in the U-Boot source code, such as:

Start of U-Boot execution.
Device initialization (e.g., storage, network, display).
Handoff to the Linux kernel.

Example:

static int initr_bootstage(void)
{

        printf("U-Boot start timestamp: %lu ms\n", get_timer(0));
        bootstage_mark_name(BOOTSTAGE_ID_START_UBOOT_R, "board_init_r");
        printf("Kernel handoff timestamp: %lu ms\n", get_timer(0));
        return 0;
}

Use the get_timer() API:

The get_timer() function returns the elapsed time in milliseconds since the last reset.

Access the bootstage logs

Print bootstage information:

After enabling CONFIG_BOOTSTAGE, U-Boot will automatically log timestamps to the serial console if the bootstage commands are enabled. Use the bootstage command in U-Boot to print timestamps:

    bootstage

Analyze bootstage output:

The output will include timestamps and labels for each recorded stage, such as:

        ID    Stage                             Time (ms)
        0     U-Boot Start                      0
        1     Device Initialization             120
        2     Handoff to Kernel                 340

Save logs for analysis

Use a serial console tool (e.g., picocom, screen, or putty) to capture the output from the UART/serial console. Redirect the output to a log file for later analysis.

Use bootloader environment variables

For additional timing markers, you can use U-Boot environment variables:

Add environment commands to measure time explicitly, e.g.:

    setenv start_time ${time}
    run load_kernel
    setenv kernel_time ${time}

Subtract the values later for measuring elapsed times.

By enabling and using timestamps in U-Boot, you can accurately measure the time spent in the firmware and bootloader stages, allowing you to identify and optimize any bottlenecks.

Optimize kernel boot time

Optimize initramfs

If you are using an initramfs, reduce its size and contents by including only necessary modules and binaries. Measure the time taken to mount the root filesystem in dmesg:

    [    X.XXXXX] VFS: Mounted root (ext4 filesystem) on device 8:1.

Profile boot with ftrace

Use the kernel’s ftrace tool to get detailed timing information:

Enable CONFIG_FUNCTION_TRACER and related options in the kernel.
Mount the tracefs filesystem

mount -t tracefs nodev /sys/kernel/debug/tracing

Start tracing:

echo function_graph > /sys/kernel/debug/tracing/current_tracer

Analyze the trace file:

        cat /sys/kernel/debug/tracing/trace

Optimize the slow subsystems

Optimizing slow subsystems in Linux requires a systematic approach to identifying bottlenecks, reducing overhead, and fine-tuning the kernel, services, and drivers. This guide provides a comprehensive strategy for addressing slow subsystems in Linux, particularly in embedded or industrial environments where performance and startup time are critical.

Identify slow drivers or services

The initcall_debug kernel parameter is a powerful tool for debugging and optimizing the boot time of a Linux kernel. It provides detailed insights into the initialization process of various kernel components, allowing you to identify and address bottlenecks.

What is initcall_debug?

When initcall_debug is passed as a kernel parameter, it enables detailed logging of the initialization times for all functions invoked during the kernel’s initialization phase. This includes initcalls for drivers, subsystems, and other components.

Each initcall logs:

Start of Initialization: The name of the function being called.
End of Initialization: The return value and the time taken to execute the function.

How to Use initcall_debug ?

Add initcall_debug to the Kernel Command Line:
- Edit your bootloader configuration
- Append initcall_debug to the kernel command line

linux /boot/vmlinuz-linux root=/dev/sda1 initcall_debug

Save the changes and reboot the system.
View the output in logs
- Once the system boots, check the kernel logs using dmesg

dmesg | grep initcall

Alternatively, view logs from the serial console or a log file if the system is headless.

Example output:

[    0.123456] calling  init_memory_subsystem+0x0/0x100
[    0.234567] initcall init_memory_subsystem+0x0/0x100 returned 0 after 111 ms
[    0.345678] calling  init_networking+0x0/0x200
[    0.456789] initcall init_networking+0x0/0x200 returned 0 after 111 ms

Key details:

calling: Indicates the function being called.
returned: Indicates the return status (e.g., 0 for success).
after: Shows the time taken to execute the function in milliseconds.

Kernel initcall levels:

Initcalls in the kernel are categorized into levels based on when they are executed during boot:

pure_initcall: Runs as early as possible.
core_initcall: Initializes core kernel components.
postcore_initcall: Runs after the core initcalls.
arch_initcall: Architecture-specific initialization.
subsys_initcall: Subsystem initialization.
fs_initcall: Filesystem initialization.
device_initcall: Device driver initialization.
late_initcall: Late initialization tasks.

initcall_debug logs the execution time for each of these levels, helping you identify the stage where bottlenecks occur.

why kernel boot time varies

Although in theory a statically compiled Linux kernel on fixed hardware should boot in a reproducible amount of time, in practice the kernel boot time can vary — often by several hundred milliseconds, sometimes more. This variation is caused by multiple factors:

asynchronous events and scheduler behavior

The Linux kernel initializes many subsystems and drivers concurrently. The exact order of execution can vary due to:

asynchronous hardware interrupts (IRQs),
slight timing differences in when devices are probed,
variations in task scheduling and CPU context switches.

Even with a single CPU core, small fluctuations in execution order can affect the total boot time.

hardware detection variability

The kernel probes all available devices during boot (PCI, USB, storage, etc.). This probing is not always deterministic and can vary due to:

device firmware response time,
peripheral readiness (e.g., USB devices waking up),
dynamic buses or hotplug-capable interfaces.

These factors can introduce inconsistent delays during hardware initialization.

CPU frequency scaling and thermal conditions

If CPU frequency scaling is enabled, the kernel might run at different speeds depending on:

power management state at boot,
thermal conditions (cold vs warm boot),
BIOS/UEFI influence over initial CPU clock rates.

This affects how fast the kernel can execute early instructions.

microarchitectural and cache state

Caches (L1/L2/L3), branch predictors, and memory buffers may start in different states depending on previous boots or system resets. These internal variations can slightly impact execution time in low-level routines.

entropy and randomness sources

While this primarily affects userspace, some early kernel operations may rely on hardware randomness or entropy sources, which can cause slight delays depending on timing and availability.

Overview

redpesk OS releases

Security updates

Application Framework Manager

Application Framework Binder

APIs & Services

Security manager

Trusted Boot

Recovery features

redpak

Minimal image

Zephyr in Redpesk

Mender redpesk (OTA)

Hardware support