ChromiumOS > Guides >

Tools for measuring boot time performance

This is a short summary of selected tools for measuring boot time performance. The bootperf command is used to run boot time performance tests on a target device. The showbootdata command can display average results from previous runs of bootperf. The bootstat_summary command computes and displays timings from a single boot.

Requirements for bootperf

As of January, 2021, the `bootperf` wrapper uses tast instead of `test_that` (autotest). In any case, one is required to build a test image, put the target test device into developer mode, and install the test image on the targeted Chrome OS device. Once the test image is installed, attach the device to a wired ethernet network and obtain the IP address by clicking on the network selection icon in the status box with the battery status indicator.

Verified boot and performance

A word of warning about verified boot: If cros build-image is invoked with the --no-enable-rootfs-verification option, this will substantially impact measured boot time: The option measurably speeds up boot. To do a fair, apples-to-apples comparison of two images, one must build both images with the same setting of the option.

Also, the performance results observed with verification off are not comparable to when verification is on, and vice-versa. The Chromium/Chrome OS boot time requirements generally only apply to systems with root verification enabled. Claims a change makes things faster, or slower, or has no impact are NOT proven until those changes are tested with root verification enabled and compared to the same build version without those changes.

Last tip: developer mode has a boot delay and beeps on each boot. To quietly boot with a much shorter "developer screen" pause, set GBB flags to 0x39. On most platforms (e.g. not on sarien) this can be done with:

localhost ~ # /usr/bin/futility gbb --set --flash --flags=0x39

What Constitutes a "Significant" Change

Statistically, the boot time performance numbers tend to have a high variance across runs. Moreover, small changes can't be perceived by ordinary human users. To claim that a particular change in performance is good (or bad), one generally needs the following:

The "before" and "after" test samples should both include at least 50 cycles.
The "before" and "after" results should show a change of at least 0.1 seconds (100 ms) to the kernel to login screen time. Changes just to intermediate phases don't count.

Changes that don't reach this threshold can be considered performance neutral. For changes clearly below the threshold, focus instead on software engineering questions such as "will it fix a bug?", or "will it make the code easier to maintain?".

An example with bootperf

Running the test

The bootperf command is run from inside the ChromiumOS chroot environment; run cros_sdk before using the script. The command should be on the default PATH inside the chroot.

(cros-chroot) ~/trunk/src/scripts $ bootperf -o ~/bootdata/bootperf.sample 172.22.75.70 2
16:34:58 - /home/jrbarnette/bootdata/bootperf.sample/run.000/log.txt
16:40:18 - /home/jrbarnette/bootdata/bootperf.sample/run.001/log.txt
16:45:23
(cros-chroot) ~/trunk/src/scripts $

In the example above, the -o option specifies a directory where the test results will be stored. If the directory doesn't exist, it will be created. The first argument is the IP address of the target device; the second argument is the number of test runs to execute.

Each test iteration will reboot the target device 10 times. One can expect autotest to spend about 30 to 60 seconds per boot cycle, or 5-10 minutes per iteration.

Looking at results

After running bootperf, use the showbootdata command to display the results in a usable form. The showbootdata command can be run from in- or outside of the chroot; this example shows it from inside.

(cros-chroot) ~/trunk/src/scripts $ showbootdata ~/bootdata/bootperf.sample
(on 20 cycles):
 time  s%     dt  s%  event
 2311  0%  +2311  0%  startup
 2587  1%   +276  5%  startup_done
 4420  1%  +1833  2%  x_started
 4464  1%    +44 11%  chrome_exec
 4482  1%    +18 41%  chrome_main
 5284  1%   +802  2%  login
 6207  9%   +923 60%  network
(cros-chroot) ~/trunk/src/scripts $

The output shows these columns:

Average total time in milliseconds
Sample standard deviation of the total time as a percentage of the average
The average time difference between the current line and the previous line's total
Sample standard deviation of the differences (over all boot iterations) between the current and previous lines, as a percent of the average
The name of the event (point in boot) at which the statistic was measured

The events listed in the output correspond to particular points in source code where sample data is taken. The samples record accumulated time since kernel startup; they don't include time spent in the firmware. The events correspond to the following points in boot:

startup: This event marks the beginning of the chromeos_startup script. This script is triggered by the startup event, which is the first event emitted by /sbin/init at boot. This timestamp represents (roughly) the moment when the system first starts running user processes.
startup_done: This marks the point when chromeos_startup finishes running. This is roughly the moment of the started boot-services event.
x_started: This marks the point in session_manager_setup.sh when the X server has completed initialization, and is ready to accept requests. This is also the point at which session_manager starts running.
chrome_exec: This marks the point when session_manager starts the chrome browser.
chrome_main: This marks a point early in Chrome initialization, after starting main().
login: This marks completion of the boot-complete upstart job, which is triggered when the chrome browser displays the login screen.
network: This marks the point when shill records that a default network route has been added.

Other summaries

The boot performance tests gather more than just boot time data from kernel startup. The -k option to showbootdata can be used to display various sets of Autotest keyvals for the test:

-k boot (the default) shows boot time statistics measured from kernel startup.
-k disk shows disk read statistics (in millions of bytes) measured from kernel startup.
-k firmware shows firmware timings measured from power on.
-k reboot shows boot time statistics measured from the start of the shutdown prior to boot.

Below is an example with -k reboot:

(cros-chroot) ~/trunk/src/scripts $ showbootdata -k reboot ~/bootdata/bootperf.sample
(on 20 cycles):
 diskrd  s%    delta  s%  event
   3569 19%    +3569 19%  shutdown
   4481 15%     +912  1%  firmware
   6791 10%    +2310  0%  startup
   8945  8%    +2154  1%  chrome_exec
   9765  7%     +820  2%  login

As with -k boot, the times are measured in milliseconds. The events correspond to the following points in the reboot sequence:

shutdown: This marks the end of shutdown, when the system hands control back to the firmware to request reboot.
firmware: This marks the end of firmware startup and kernel decompression, when the kernel begins initialization.
startup, chrome_exec, login: These are the same as the boot time events described above.

Raw results

To process the data with custom scripts, raw results can be extracted using the -r option to showbootdata.

(cros-chroot) ~/trunk/src/scripts $ showbootdata -r ~/bootdata/bootperf.sample
  0  2310  2560  4420  4470  4490  5290  6070
  1  2310  2580  4370  4420  4440  5250  6070
  2  2330  2600  4480  4520  4550  5360  6060
  3  2320  2610  4430  4480  4490  5270  6350
  4  2310  2600  4390  4440  4450  5230  6050
  5  2310  2580  4430  4470  4490  5280  6070
  6  2290  2550  4350  4400  4410  5220  6040
  7  2320  2590  4430  4470  4490  5300  6060
  8  2320  2620  4420  4460  4480  5270  6090
  9  2320  2590  4450  4500  4510  5330  6050
 10  2310  2600  4440  4480  4490  5330  6050
 11  2300  2590  4400  4450  4460  5260  6100
 12  2310  2580  4430  4470  4480  5290  6130
 13  2300  2570  4380  4420  4440  5230  6120
 14  2310  2580  4440  4480  4500  5290  6050
 15  2320  2600  4400  4450  4460  5260  8510
 16  2310  2570  4430  4480  4500  5300  6090
 17  2290  2570  4410  4450  4470  5260  6060
 18  2310  2590  4450  4490  4520  5350  6040
 19  2310  2600  4440  4480  4510  5310  6070
(cros-chroot) ~/trunk/src/scripts $

The first column is the iteration number; the remaining columns correspond to the time sampled at the corresponding event. In this example there were twenty boot time data points, so there are twenty lines of output. Note that the event names (and order) are implicit.

Data displayed can be restricted to selected events using the -e option.

(cros-chroot) ~/trunk/src/scripts $ showbootdata -e startup,chrome_exec,login ~/bootdata/bootperf.sample
(on 20 cycles):
 time  s%     dt  s%  event
 2311  0%  +2311  0%  startup
 4464  1%  +2153  1%  chrome_exec
 5284  1%   +820  2%  login

Using bootstat_summary

The bootstat_summary command is a device-resident command used to show the timings of events since the last boot. The command is different from bootperf and showbootdata in that it is run on the target device, and it can't show an average across multiple boots. The command is present in all images; a test image is not required to use the command.

Here's a sample:

chronos@localhost ~ $ bootstat_summary
 time %cpu    dt  %dt  event
 1060  22%  1060  22%  pre-startup
 1390  37%   330  86%  post-startup
 3260  72%  1870  97%  x-started
 3370  72%   110  89%  chrome-exec
 4090  76%   720  92%  chrome-main
 5620  65%  1530  37%  login-prompt-ready
 6460  64%   840  57%  network-ethernet-configuration
 6490  64%    30  50%  network-ethernet-ready
 6500  64%    10  50%  network-ethernet-online
 6540  64%    40  56%  network-ethernet-ready
 6550  64%    10  75%  network-ethernet-online
 8310  60%  1760  43%  login-prompt-visible
 8340  60%    30  83%  boot-complete
chronos@localhost ~ $

The listed events include the events reported in showbootdata (using slightly different names), plus some additional events. The meaning of the columns is covered below:

time: Timestamp for the event, measured in milliseconds since boot.
%cpu: Total CPU utilization since boot.
dt: Time in milliseconds since the previous event
%dt: CPU utilization in the interval since the previous event.
event: The name of the event.

The events reported in showbootdata are a subset of the events reported by bootstat_summary. Here's the correspondence between the two:

`bootstat_summary`	`showbootdata`
pre-startup	startup
post-startup	startup_done
x-started	x_started
chrome-exec	chrome_exec
chrome-main	chrome_main
boot-complete	login
network-ethernet-ready	network

N.B. The CPU utilization values can be inaccurate for short intervals (less than a few hundred milliseconds). In some cases, one may even see negative utilization. This is a limitation in the underlying kernel code that produces the statistics.