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