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 can show you timings from a single boot.
Requirements for bootperf
The bootperf script uses run_remote_tests.sh, which requires that you build an autotest-enabled image and install it on your target device. Once the image is installed, the device must be attached to the network, and you'll need to know its IP address. The IP address can be easily obtained 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 you use build_image with the --noenable_rootfs_verification option, this will substantially impact measured boot time: The option measurably speeds up boot. If you want to do a fair, apples-to-apples comparison of two images, you must build both images with the same setting of the option. Also, be aware that performance results observed with verification off may not be applicable when verification is on, and vice-versa. The Chromium/Chrome OS boot time requirements generally only apply to systems with root verification enabled. Put another way: If you want to claim a change makes things faster, or slower, or has no impact, the claim isn't proven until it's tested with root verification enabled.
An example with bootperf
Running the test
The bootperf command is run from inside the Chromium OS chroot environment; run cros_sdk before using the script. The default location within the chroot is in ~/trunk/src/platform/crostestutils.
(cros-chroot) ~/trunk/src/platform/crostestutils $ bootperf-bin/bootperf -o ~/bootperf-sample 172.22.75.188 2
13:34:33 - /home/jrbarnette/bootperf-sample/run.000/log.txt
13:40:05 - /home/jrbarnette/bootperf-sample/run.001/log.txt
13:45:44
(cros-chroot) ~/trunk/src/platform/crostestutils $
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 run will reboot your target device 10 times. You can expect autotest to spend about 35 seconds (or more) per boot cycle, or slightly less than 6 minutes per run.
Looking at results
After running bootperf, the showbootdata command will 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/platform/crostestutils $ bootperf-bin/showbootdata ~/bootperf-sample
(on 20 cycles):
time s% dt s% event
1356 5% +1356 5% startup
1621 5% +265 9% startup_done
4629 17% +3008 25% network
5860 11% +1231 83% x_started
5960 10% +100 19% chrome_exec
6095 10% +135 10% chrome_main
7362 8% +1267 4% login
(cros-chroot) ~/trunk/src/platform/crostestutils $
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.
Disk read results
In addition to time statistics, the boot performance tests also record the total number of bytes read from the boot device. The information can be seen using the -d option to the showbootdata command:
(cros-chroot) ~/trunk/src/platform/crostestutils $ bootperf-bin/showbootdata -d ~/bootperf-sample
(on 20 cycles):
diskrd s% delta s% event
3.6M 2% +3.6M 2% startup
7.5M 4% +3.9M 7% startup_done
121.6M 3% +114.1M 4% x_started
122.0M 3% +0.4M 440% chrome_exec
122.2M 3% +0.2M 415% chrome_main
129.5M 2% +7.3M 2% login
(cros-chroot) ~/trunk/src/platform/crostestutils $
Data sizes are reported as millions of bytes. The event names correspond to the same points in boot as for the time statistics.
Raw results
If you want to write scripts to perform customized processing of the data, raw results can be extracted using the -r option to showbootdata.
(cros-chroot) ~/trunk/src/platform/crostestutils $ bootperf-bin/showbootdata -r ~/bootperf-sample
0 1350 1630 4310 5730 5850 5980 7240
1 1440 1680 4660 5920 6020 6180 7390
2 1340 1620 4400 4610 4760 4920 6180
3 1430 1690 4390 5690 5770 5900 7180
4 1440 1760 7930 5800 5880 6010 7300
5 1410 1670 4510 6160 6270 6390 7640
6 1420 1690 4890 5720 5840 5980 7300
7 1330 1560 4810 6460 6560 6690 7940
8 1290 1540 4320 5000 5080 5220 6420
9 1290 1550 4350 4950 5060 5170 6420
10 1280 1550 4450 5710 5820 5950 7220
11 1420 1730 4270 6950 7030 7170 8490
12 1200 1470 4250 6830 6910 7030 8380
13 1350 1590 4460 6060 6170 6320 7620
14 1260 1560 4330 5720 5800 5940 7210
15 1370 1630 4460 5420 5520 5650 6930
16 1380 1650 4510 5520 5630 5750 7000
17 1440 1680 4450 5770 5860 5990 7320
18 1270 1500 4330 6330 6410 6540 7770
19 1410 1660 4500 6840 6960 7120 8280
(cros-chroot) ~/trunk/src/platform/crostestutils $
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/platform/crostestutils $ bootperf-bin/showbootdata -r -e x_started,login ~/bootperf-sample
0 5730 7240
1 5920 7390
2 4610 6180
3 5690 7180
4 5800 7300
5 6160 7640
6 5720 7300
7 6460 7940
8 5000 6420
9 4950 6420
10 5710 7220
11 6950 8490
12 6830 8380
13 6060 7620
14 5720 7210
15 5420 6930
16 5520 7000
17 5770 7320
18 6330 7770
19 6840 8280
(cros-chroot) ~/trunk/src/platform/crostestutils $
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 you run it on the target device, and it can't show an average across multiple boots. The command is present in all images; you do not need a test image 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
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, you may even see negative utilization. This is a limitation in the underlying kernel code that produces the statistics.
