The boot_metrics.log file

You can use the boot_metrics.log file to monitor startup times for your system.

The boot_metrics.log file contains time measurements from board reset to a particular system event (the time from board reset varies depending on your platform).

Note: Although this log is purely for reference purposes, you can get important information from it that can help you tune your system startup.

Variation in timers

Each measurement in the log starts with either (hw) or (sw):
  • Times that start with (hw) are measured using a simple utility called timestamp that makes a call to the ClockCycles() kernel function. This function provides the timestamp utility with the number of clock cycles since the board was reset. Note that these measurements aren't entirely accurate because they're taken close to—but not simultaneously with—the event that's being measured. The timestamp utility is just a process that's run in the background at a normal priority, as closely as possible to the event being measured.
  • Times that start with (sw) are doing some other measurement, like querying the system for the date.

On some boards, the time reported by the timestamp utility correlates very closely with the time elapsed since power was actually applied to the board (i.e., a board reset was done either in software or by pressing the reset button). This is the most desirable implementation. In some cases, however, the time reported by the timestamp utility could represent the time since the IPL started, or even the time since the startup driver started. This situation results in measurements that are much smaller than would be observed using a stopwatch from power on. These measurements are obviously less accurate, but can still be useful in comparing one software build to another.

The particular measurements you get depend on whether:
  • the board provides a counter in the hardware that starts as close as possible to power-on reset (PoR). If the board doesn't provide a hardware counter, you can use the counter provided in the kernel, but it won't start counting until the kernel takes control, which is well after PoR.
  • the IPL/startup driver can (or actually does) initialize this hardware counter to zero.
  • the startup driver performs a "cold" or "warm" reset on shutdown (software reset). A cold reset generally initializes the hardware more thoroughly than a warm reset, so a cold reset would be more likely to set the hardware counter to 0.

Contents of boot_metrics.log

The boot_metrics.log is found in the /dev/shmem directory. Its contents look like this:

(hw) CAR_BOOT_METRICS: (IFS SCRIPT START) at 0.484901 seconds 
(hw) CAR_BOOT_METRICS: (LAUNCHING EARLY-SPLASH) at 0.629556 seconds 
(hw) CAR_BOOT_METRICS: (REARVIEW CAMERA DONE) at 0.632296 seconds 
(hw) CAR_BOOT_METRICS: (LAUNCHING EARLY-CHIME) at 0.661630 seconds 
(hw) CAR_BOOT_METRICS: (STARTING PPS) at 0.759833 seconds 
(hw) CAR_BOOT_METRICS: (LAUNCHING PPS) at 0.798557 seconds 
(hw) CAR_BOOT_METRICS: (LAUNCHING MOUNT-IFS2) at 0.815651 seconds 
(hw) CAR_BOOT_METRICS: (LAUNCHING SLM) at 0.852900 seconds 
(hw) CAR_BOOT_METRICS: (DONE MOUNT-IFS2) at 1.161844 seconds 
(hw) CAR_BOOT_METRICS: (STARTING SLOGGER2) at 1.354558 seconds 
(hw) CAR_BOOT_METRICS: (DONE PPS (/pps is available)) at 1.364052 seconds 
(hw) CAR_BOOT_METRICS: (HMI LAUNCHED) at 1.837985 seconds 
(hw) CAR_BOOT_METRICS: (DONE WEB-ZYGOTE) at 2.514162 seconds 
(hw) CAR_BOOT_METRICS: (DONE EARLY-CHIME) at 2.746928 seconds 
(hw) CAR_BOOT_METRICS: (MMPLAYER LAUNCHED) at 3.742285 seconds 
(hw) CAR_BOOT_METRICS: (SET DATE) at 13.623120 seconds 
(sw) CAR_BOOT_METRICS: (SYSTEM DATE) at Thu Jan 30 10:16:50 EST 2014
(hw) CAR_BOOT_METRICS: (HMI LOADED) at 14.947910 seconds 

The events that appear in the log file are as shown in the following table:

This log entry: Corresponds to this system event:
IFS SCRIPT START The IFS build script has started.
LAUNCHING EARLY-SPLASH The early splash screen has been launched.
REARVIEW CAMERA DONE The rearview camera is ready.
LAUNCHING EARLY-CHIME The early audio chime has been launched.
STARTING PPS PPS has been launched.
LAUNCHING PPS PPS has been launched.
LAUNCHING MOUNT-IFS2 The process to mount the secondary IFS has been launched.
LAUNCHING SLM SLM has been launched.
EARLY-SPLASH WINDOW CREATED The early splash screen window has been created. This is close to but not necessarily exactly the same time as when you see the splash screen on the display.
DONE MOUNT-IFS2. The secondary IFS has been mounted
STARTING SLOGGER2 The slogger2 daemon has been launched.
DONE PPS (/pps is available) PPS is ready and the PPS filesystem has been mounted.
HMI LAUNCHED The HMI is ready.
DONE WEB-ZYGOTE The browser engine zygote is ready.
DONE EARLY-CHIME The early audio chime has finished playing.
MMPLAYER LAUNCHED The mm-player service is ready (so early audio is available).
SET DATE The system date has been set.
SYSTEM SECONDS The system time as reported by the POSIX-standard date –t utility.
SYSTEM DATE The current system date and time.
HMI LOADED The HMI is has loaded.

You can write additional events to the log by running the timestamp utility (e.g., timestamp event_name). The event information will be written to /dev/shmem/boot_metrics.log.