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