1# Copyright (c) 2009 The Chromium OS Authors. All rights reserved. 2# Use of this source code is governed by a BSD-style license that can be 3# found in the LICENSE file. 4 5import glob 6import logging 7import os 8import re 9import shutil 10import time 11import utils 12 13from autotest_lib.client.bin import test 14from autotest_lib.client.common_lib import error 15 16class platform_BootPerf(test.test): 17 """Test to gather recorded boot time statistics. 18 19 The primary function of this test is to gather a rather large 20 assortment of performance keyvals that capture timing and disk 21 usage statistics associated with the most recent boot or reboot. 22 23 The test calculates some or all of the following keyvals: 24 * seconds_kernel_to_startup 25 * seconds_kernel_to_startup_done 26 * seconds_kernel_to_x_started 27 * seconds_kernel_to_chrome_exec 28 * seconds_kernel_to_chrome_main 29 * seconds_kernel_to_signin_start 30 * seconds_kernel_to_signin_wait 31 * seconds_kernel_to_signin_users 32 * seconds_kernel_to_login 33 * seconds_kernel_to_network 34 * rdbytes_kernel_to_startup 35 * rdbytes_kernel_to_startup_done 36 * rdbytes_kernel_to_x_started 37 * rdbytes_kernel_to_chrome_exec 38 * rdbytes_kernel_to_chrome_main 39 * rdbytes_kernel_to_login 40 * seconds_power_on_to_lf_start 41 * seconds_power_on_to_lf_end 42 * seconds_power_on_to_lk_start 43 * seconds_power_on_to_lk_end 44 * seconds_power_on_to_kernel 45 * seconds_power_on_to_login 46 * seconds_shutdown_time 47 * seconds_reboot_time 48 * seconds_reboot_error 49 * mhz_primary_cpu 50 51 """ 52 53 version = 2 54 55 # Names of keyvals, their associated bootstat events, and 'Required' flag. 56 # Test fails if a required event is not found. 57 # Each event samples statistics measured since kernel startup 58 # at a specific moment on the boot critical path: 59 # pre-startup - The start of the `chromeos_startup` script; 60 # roughly, the time when /sbin/init emits the `startup` 61 # Upstart event. 62 # post-startup - Completion of the `chromeos_startup` script. 63 # x-started - Completion of X server initialization. 64 # chrome-exec - The moment when session_manager exec's the 65 # first Chrome process. 66 # chrome-main - The moment when the first Chrome process 67 # begins executing in main(). 68 # kernel_to_signin_start - The moment when LoadPage(loginSceenURL) 69 # is called, i.e. initialization starts. 70 # kernel_to_signin_wait - The moment when UI thread has finished signin 71 # screen initialization and now waits until JS sends "ready" event. 72 # kernel_to_signin_users - The moment when UI thread receives "ready" from 73 # JS code. So V8 is initialized and running, etc... 74 # kernel_to_login - The moment when user can actually see signin UI. 75 # kernel_to_android_start - The moment when Android is started. 76 _EVENT_KEYVALS = [ 77 # N.B. Keyval attribute names go into a database that 78 # truncates after 30 characters. The key names below are 79 # prefixed with 8 characters, either 'seconds_' or 80 # 'rdbytes_', so we have 22 characters wiggle room. 81 # 82 # ----+----1----+----2-- 83 ('kernel_to_startup', 'pre-startup', True), 84 ('kernel_to_startup_done', 'post-startup', True), 85 ('kernel_to_chrome_exec', 'chrome-exec', True), 86 ('kernel_to_chrome_main', 'chrome-main', True), 87 # These two events do not happen if device is in OOBE. 88 ('kernel_to_signin_start', 'login-start-signin-screen', False), 89 ('kernel_to_signin_wait', 90 'login-wait-for-signin-state-initialize', False), 91 # This event doesn't happen if device has no users. 92 ('kernel_to_signin_users', 'login-send-user-list', False), 93 ('kernel_to_login', 'login-prompt-visible', True), 94 # Not all boards support ARC. 95 ('kernel_to_android_start', 'android-start', False) 96 ] 97 98 _CPU_FREQ_FILE = ('/sys/devices/system/cpu/cpu0' 99 '/cpufreq/cpuinfo_max_freq') 100 101 _UPTIME_PREFIX = 'uptime-' 102 _DISK_PREFIX = 'disk-' 103 104 _FIRMWARE_TIME_FILE = '/tmp/firmware-boot-time' 105 106 _BOOTSTAT_ARCHIVE_GLOB = '/var/log/metrics/shutdown.[0-9]*' 107 _UPTIME_FILE_GLOB = os.path.join('/tmp', _UPTIME_PREFIX + '*') 108 _DISK_FILE_GLOB = os.path.join('/tmp', _DISK_PREFIX + '*') 109 110 # The name of this file has changed starting with linux-3.19. 111 # Use a glob to snarf up all existing records. 112 _RAMOOPS_FILE_GLOB = "/sys/fs/pstore/console-ramoops*" 113 114 115 def _copy_timestamp_files(self): 116 """Copy raw data files to the test results.""" 117 statlist = (glob.glob(self._UPTIME_FILE_GLOB) + 118 glob.glob(self._DISK_FILE_GLOB)) 119 for fname in statlist: 120 shutil.copy(fname, self.resultsdir) 121 try: 122 shutil.copy(self._FIRMWARE_TIME_FILE, self.resultsdir) 123 except Exception: 124 pass 125 126 def _copy_console_ramoops(self): 127 """Copy console_ramoops from previous reboot.""" 128 # If reboot was misbehaving, looking at ramoops may provide clues. 129 for path in glob.glob(self._RAMOOPS_FILE_GLOB): 130 try: 131 shutil.copy(path, self.resultsdir) 132 break 133 except Exception: 134 pass 135 136 def _parse_bootstat(self, filename, fieldnum): 137 """Read values from a bootstat event file. 138 139 Each line of a bootstat event file represents one occurrence 140 of the event. Each line is a copy of the content of 141 /proc/uptime ("uptime-" files) or /sys/block/<dev>/stat 142 ("disk-" files), captured at the time of the occurrence. 143 For either kind of file, each line is a blank separated list 144 of fields. 145 146 The given event file can contain either uptime or disk data. 147 This function reads all lines (occurrences) in the event 148 file, and returns the value of the given field 149 150 @param filename Filename of the bootstat event. 151 @param fieldnum Which field of the file. 152 @return List of values of `fieldnum` for 153 all occurrences in the file. 154 @raises error.TestFail Raised if the event file is missing, 155 unreadable, or malformed. 156 157 """ 158 try: 159 with open(filename) as statfile: 160 values = map(lambda l: float(l.split()[fieldnum]), 161 statfile.readlines()) 162 return values 163 except IOError: 164 raise error.TestFail('Failed to read bootstat file "%s"' % 165 filename) 166 167 168 def _parse_uptime(self, eventname, bootstat_dir='/tmp', index=0): 169 """Return time since boot for a bootstat event. 170 171 @param eventname Name of the bootstat event. 172 @param boostat_dir Directory containing the bootstat 173 files. 174 @param index Index of which occurrence of the event 175 to select. 176 @return Time since boot for the selected 177 event. 178 179 """ 180 event_file = os.path.join(bootstat_dir, 181 self._UPTIME_PREFIX) + eventname 182 return self._parse_bootstat(event_file, 0)[index] 183 184 185 def _parse_diskstat(self, eventname, bootstat_dir='/tmp', index=0): 186 """Return sectors read since boot for a bootstat event. 187 188 @param eventname Name of the bootstat event. 189 @param boostat_dir Directory containing the bootstat files. 190 @param index Index of which occurrence of the event 191 to select. 192 @return Number of sectors read since boot for 193 the selected event. 194 195 """ 196 event_file = os.path.join(bootstat_dir, 197 self._DISK_PREFIX) + eventname 198 return self._parse_bootstat(event_file, 2)[index] 199 200 201 def _gather_vboot_times(self, results): 202 """Read and report firmware internal timestamps. 203 204 The firmware for all Chrome platforms except Mario records 205 the ticks since power on at selected times during startup. 206 These timestamps can be extracted from the `crossystem` 207 command. 208 209 If the timestamps are available, convert the tick times to 210 seconds and record the following keyvals in `results`: 211 * seconds_power_on_to_lf_start 212 * seconds_power_on_to_lf_end 213 * seconds_power_on_to_lk_start 214 * seconds_power_on_to_lk_end 215 216 The frequency of the recorded tick timestamps is determined 217 by reading `_CPU_FREQ_FILE` and is recorded in the keyval 218 mhz_primary_cpu. 219 220 @param results Keyvals dictionary. 221 222 """ 223 try: 224 khz = int(utils.read_one_line(self._CPU_FREQ_FILE)) 225 except IOError: 226 logging.info('Test is unable to read "%s", not calculating the ' 227 'vboot times.', self._CPU_FREQ_FILE) 228 return 229 hertz = khz * 1000.0 230 results['mhz_primary_cpu'] = khz / 1000.0 231 try: 232 out = utils.system_output('crossystem') 233 except error.CmdError: 234 logging.info('Unable to run crossystem, not calculating the vboot ' 235 'times.') 236 return 237 # Parse the crossystem output, we are looking for vdat_timers 238 items = out.splitlines() 239 for item in items: 240 times_re = re.compile(r'LF=(\d+),(\d+) LK=(\d+),(\d+)') 241 match = re.findall(times_re, item) 242 if match: 243 times = map(lambda s: round(float(s) / hertz, 2), match[0]) 244 results['seconds_power_on_to_lf_start'] = times[0] 245 results['seconds_power_on_to_lf_end'] = times[1] 246 results['seconds_power_on_to_lk_start'] = times[2] 247 results['seconds_power_on_to_lk_end'] = times[3] 248 249 250 def _gather_firmware_boot_time(self, results): 251 """Read and report firmware startup time. 252 253 The boot process writes the firmware startup time to the 254 file named in `_FIRMWARE_TIME_FILE`. Read the time from that 255 file, and record it in `results` as the keyval 256 seconds_power_on_to_kernel. 257 258 @param results Keyvals dictionary. 259 260 """ 261 try: 262 # If the firmware boot time is not available, the file 263 # will not exist. 264 data = utils.read_one_line(self._FIRMWARE_TIME_FILE) 265 except IOError: 266 return 267 firmware_time = float(data) 268 boot_time = results['seconds_kernel_to_login'] 269 results['seconds_power_on_to_kernel'] = firmware_time 270 results['seconds_power_on_to_login'] = ( 271 round(firmware_time + boot_time, 2)) 272 273 274 def _gather_time_keyvals(self, results): 275 """Read and report boot time keyvals. 276 277 Read "seconds since kernel startup" from the bootstat files 278 for the events named in `_EVENT_KEYVALS`, and store the 279 values as perf keyvals. The following keyvals are recorded: 280 * seconds_kernel_to_startup 281 * seconds_kernel_to_startup_done 282 * seconds_kernel_to_x_started 283 * seconds_kernel_to_chrome_exec 284 * seconds_kernel_to_chrome_main 285 * seconds_kernel_to_login 286 * seconds_kernel_to_network 287 All of these keyvals are considered mandatory, except 288 for seconds_kernel_to_network. 289 290 @param results Keyvals dictionary. 291 @raises error.TestFail Raised if any mandatory keyval can't 292 be determined. 293 294 """ 295 for keyval_name, event_name, required in self._EVENT_KEYVALS: 296 key = 'seconds_' + keyval_name 297 try: 298 results[key] = self._parse_uptime(event_name) 299 except error.TestFail: 300 if required: 301 raise; 302 303 # Not all 'uptime-network-*-ready' files necessarily exist; 304 # probably there's only one. We go through a list of 305 # possibilities and pick the first one we find. We're not 306 # looking for 3G here, so we're not guaranteed to find any 307 # file. 308 network_ready_events = [ 309 'network-wifi-ready', 310 'network-ethernet-ready' 311 ] 312 313 for event_name in network_ready_events: 314 try: 315 network_time = self._parse_uptime(event_name) 316 results['seconds_kernel_to_network'] = network_time 317 break 318 except error.TestFail: 319 pass 320 321 322 def _gather_disk_keyvals(self, results): 323 """Read and report disk read keyvals. 324 325 Read "sectors read since kernel startup" from the bootstat 326 files for the events named in `_EVENT_KEYVALS`, convert the 327 values to "bytes read since boot", and store the values as 328 perf keyvals. The following keyvals are recorded: 329 * rdbytes_kernel_to_startup 330 * rdbytes_kernel_to_startup_done 331 * rdbytes_kernel_to_x_started 332 * rdbytes_kernel_to_chrome_exec 333 * rdbytes_kernel_to_chrome_main 334 * rdbytes_kernel_to_login 335 336 Disk statistics are reported in units of 512 byte sectors; 337 we convert the keyvals to bytes so that downstream consumers 338 don't have to ask "How big is a sector?". 339 340 @param results Keyvals dictionary. 341 342 """ 343 # We expect an error when reading disk statistics for the 344 # "chrome-main" event because Chrome (not bootstat) generates 345 # that event, and it doesn't include the disk statistics. 346 # We get around that by ignoring all errors. 347 for keyval_name, event_name, required in self._EVENT_KEYVALS: 348 try: 349 key = 'rdbytes_' + keyval_name 350 results[key] = 512 * self._parse_diskstat(event_name) 351 except Exception: 352 pass 353 354 355 def _calculate_timeval(self, event, t0, t1, t_uptime): 356 """Estimate the absolute time of a time since boot. 357 358 Input values `event` and `t_uptime` are times measured as 359 seconds since boot (for the same boot event, as from 360 /proc/uptime). The input values `t0` and `t1` are two 361 values measured as seconds since the epoch. The three "t" 362 values were sampled in the order `t0`, `t_uptime`, `t1`. 363 364 Estimate the time of `event` measured as seconds since the 365 epoch. Also estimate the worst-case error based on the time 366 elapsed between `t0` and `t1`. 367 368 All values are floats. The precision of `event` and 369 `t_uptime` is expected to be kernel jiffies (i.e. one 370 centisecond). The output result is rounded to the nearest 371 jiffy. 372 373 @param event A time to be converted from "seconds since 374 boot" into "seconds since the epoch". 375 @param t0 A reference time earlier than time `t1`, and 376 measured as "seconds since the epoch". 377 @param t1 A reference time later than time `t0`, and 378 measured as "seconds since the epoch". 379 @param t_uptime A reference time measured as "seconds since 380 boot", in between time `t0` and `t1`. 381 382 @return An estimate of the time of `event` measured 383 as seconds since the epoch, rounded to the 384 nearest jiffy. 385 386 """ 387 # Floating point geeks may argue that these calculations 388 # don't guarantee the promised precision: I don't care; 389 # it's good enough. 390 boot_timeval = round((t0 + t1) / 2, 2) - t_uptime 391 error = (t1 - t0) / 2 392 return boot_timeval + event, error 393 394 395 def _gather_reboot_keyvals(self, results): 396 """Read and report shutdown and reboot times. 397 398 The shutdown process saves all bootstat files in /var/log, 399 plus it saves a timestamp file that can be used to convert 400 "time since boot" into times in UTC. Read the saved files 401 from the most recent shutdown, and use them to calculate 402 the time spent from the start of that shutdown until the 403 completion of the most recent boot. Record these keyvals: 404 * seconds_shutdown_time 405 * seconds_reboot_time 406 * seconds_reboot_error 407 408 @param results Keyvals dictionary. 409 410 """ 411 bootstat_archives = glob.glob(self._BOOTSTAT_ARCHIVE_GLOB) 412 if not bootstat_archives: 413 return 414 bootstat_dir = max(bootstat_archives) 415 boot_id = open("/proc/sys/kernel/random/boot_id", "r").read() 416 didrun_path = os.path.join(bootstat_dir, "bootperf_ran") 417 if not os.path.exists(didrun_path): 418 with open(didrun_path, "w") as didrun: 419 didrun.write(boot_id) 420 elif open(didrun_path, "r").read() != boot_id: 421 logging.warning("Ignoring reboot based on stale shutdown %s", 422 os.path.basename(bootstat_dir)) 423 return 424 timestamp_path = os.path.join(bootstat_dir, 'timestamp') 425 try: 426 with open(timestamp_path) as timestamp: 427 archive_t0 = float(timestamp.readline()) 428 archive_t1 = float(timestamp.readline()) 429 except IOError: 430 raise error.TestFail('Failed to read "%s"' % timestamp_path) 431 archive_uptime = self._parse_uptime('archive', 432 bootstat_dir=bootstat_dir) 433 shutdown_uptime = self._parse_uptime('ui-post-stop', 434 bootstat_dir=bootstat_dir, 435 index=-1) 436 shutdown_timeval, shutdown_error = self._calculate_timeval( 437 shutdown_uptime, archive_t0, archive_t1, archive_uptime) 438 boot_t0 = time.time() 439 with open('/proc/uptime') as uptime_file: 440 uptime = float(uptime_file.readline().split()[0]) 441 boot_t1 = time.time() 442 boot_timeval, boot_error = self._calculate_timeval( 443 results['seconds_kernel_to_login'], 444 boot_t0, boot_t1, uptime) 445 reboot_time = round(boot_timeval - shutdown_timeval, 2) 446 poweron_time = results['seconds_power_on_to_login'] 447 shutdown_time = round(reboot_time - poweron_time, 2) 448 results['seconds_reboot_time'] = reboot_time 449 results['seconds_reboot_error'] = shutdown_error + boot_error 450 results['seconds_shutdown_time'] = shutdown_time 451 452 453 def run_once(self): 454 """Gather boot time statistics. 455 456 Every shutdown and boot creates `bootstat` files with 457 summary statistics for time elapsed and disk usage. Gather 458 the values reported for shutdown, boot time and network 459 startup time, and record them as perf keyvals. 460 461 Additionally, gather information about firmware startup time 462 from various sources, and record the times as perf keyvals. 463 464 Finally, copy the raw data files to the results directory 465 for reference. 466 467 """ 468 # `results` is the keyvals dictionary 469 results = {} 470 471 self._gather_time_keyvals(results) 472 self._gather_disk_keyvals(results) 473 self._gather_firmware_boot_time(results) 474 self._gather_vboot_times(results) 475 self._gather_reboot_keyvals(results) 476 477 self._copy_timestamp_files() 478 self._copy_console_ramoops() 479 480 self.write_perf_keyval(results) 481