1# Copyright (c) 2012 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 collections, logging, os, re, subprocess, time 6 7from autotest_lib.client.bin import utils 8from autotest_lib.client.common_lib import error 9from autotest_lib.client.cros import cros_logging 10from autotest_lib.client.cros.power import power_status 11from autotest_lib.client.cros.power import power_utils 12from autotest_lib.client.cros.power import sys_power 13#pylint: disable=W0611 14from autotest_lib.client.cros import flimflam_test_path 15import flimflam 16 17class Suspender(object): 18 """Class for suspend/resume measurements. 19 20 Public attributes: 21 disconnect_3G_time: Amount of seconds it took to disable 3G. 22 successes[]: List of timing measurement dicts from successful suspends. 23 failures[]: List of SuspendFailure exceptions from failed suspends. 24 device_times[]: List of individual device suspend/resume time dicts. 25 26 Public methods: 27 suspend: Do a suspend/resume cycle. Return timing measurement dict. 28 29 Private attributes: 30 _logs: Array of /var/log/messages lines since start of suspend cycle. 31 _log_file: Open file descriptor at the end of /var/log/messages. 32 _logdir: Directory to store firmware logs in case of errors. 33 _suspend: Set to the sys_power suspend function to use. 34 _throw: Set to have SuspendFailure exceptions raised to the caller. 35 _reset_pm_print_times: Set to deactivate pm_print_times after the test. 36 _restart_tlsdated: Set to restart tlsdated after the test. 37 38 Private methods: 39 __init__: Shuts off tlsdated for duration of test, disables 3G 40 __del__: Restore tlsdated (must run eventually, but GC delay no problem) 41 _set_pm_print_times: Enable/disable kernel device suspend timing output. 42 _check_failure_log: Check /sys/.../suspend_stats for new failures. 43 _ts: Returns a timestamp from /run/power_manager/last_resume_timings 44 _hwclock_ts: Read RTC timestamp left on resume in hwclock-on-resume 45 _device_resume_time: Read seconds overall device resume took from logs. 46 _individual_device_times: Reads individual device suspend/resume times. 47 _identify_driver: Return the driver name of a device (or "unknown"). 48 """ 49 50 # board-specific "time to suspend" values determined empirically 51 # TODO: migrate to separate file with http://crosbug.com/38148 52 _DEFAULT_SUSPEND_DELAY = 5 53 _SUSPEND_DELAY = { 54 # TODO: Reevaluate this when http://crosbug.com/38460 is fixed 55 'daisy': 6, 56 'daisy_spring': 6, 57 'peach_pit': 6, 58 59 # TODO: Reevaluate these when http://crosbug.com/38225 is fixed 60 'x86-mario': 6, 61 'x86-alex': 5, 62 63 # Lumpy and Stumpy need high values, because it seems to mitigate their 64 # RTC interrupt problem. See http://crosbug.com/36004 65 'lumpy': 5, 66 'stumpy': 5, 67 68 # RTS5209 card reader has a really bad staging driver, can take ~1 sec 69 'butterfly': 4, 70 71 # Hard disk sync and overall just slow 72 'parrot': 8, 73 'kiev': 9, 74 } 75 76 # alarm/not_before value guaranteed to raise SpuriousWakeup in _hwclock_ts 77 _ALARM_FORCE_EARLY_WAKEUP = 2147483647 78 79 # File written by send_metrics_on_resume containing timing information about 80 # the last resume. 81 _TIMINGS_FILE = '/run/power_manager/root/last_resume_timings' 82 83 # Latest powerd log files 84 _POWERD_LOG_LATEST_PATH = '/var/log/power_manager/powerd.LATEST' 85 _POWERD_LOG_PREVIOUS_PATH = '/var/log/power_manager/powerd.PREVIOUS' 86 87 # Line to look for suspend abort due to override. 88 _ABORT_DUE_TO_OVERRIDE_LINE = 'Aborting suspend attempt for lockfile' 89 90 # Regexp to extract TS from powerd log line. 91 _POWERD_TS_RE = '\[(\d{4}/\d{6}\.\d{6}):.*\]' 92 93 # Amount of lines to dump from the eventlog on a SpuriousWakeup. Should be 94 # enough to include ACPI Wake Reason... 10 should be far on the safe side. 95 _RELEVANT_EVENTLOG_LINES = 10 96 97 # Sanity check value to catch overlong resume times (from missed RTC wakes) 98 _MAX_RESUME_TIME = 10 99 100 # File written by powerd_suspend containing the hwclock time at resume. 101 HWCLOCK_FILE = '/run/power_manager/root/hwclock-on-resume' 102 103 # File read by powerd to decide on the state to suspend (mem or freeze). 104 _SUSPEND_STATE_PREF_FILE = 'suspend_to_idle' 105 106 # (b/79442787) Ignore these uarch for s0ix residency counter checking 107 _IGNORE_S0IX_RESIDENCY_CHECK = ['Skylake'] 108 109 def __init__(self, logdir, method=sys_power.do_suspend, 110 throw=False, device_times=False, suspend_state=''): 111 """ 112 Prepare environment for suspending. 113 @param suspend_state: Suspend state to enter into. It can be 114 'mem' or 'freeze' or an empty string. If 115 the suspend state is an empty string, 116 system suspends to the default pref. 117 """ 118 self.disconnect_3G_time = 0 119 self.successes = [] 120 self.failures = [] 121 self._logdir = logdir 122 self._suspend = method 123 self._throw = throw 124 self._reset_pm_print_times = False 125 self._restart_tlsdated = False 126 self._log_file = None 127 self._powerd_cycle_start_ts = None 128 self._suspend_state = suspend_state 129 if device_times: 130 self.device_times = [] 131 132 # stop tlsdated, make sure we/hwclock have /dev/rtc for ourselves 133 if utils.system_output('initctl status tlsdated').find('start') != -1: 134 utils.system('initctl stop tlsdated') 135 self._restart_tlsdated = True 136 # give process's file descriptors time to asynchronously tear down 137 time.sleep(0.1) 138 139 # prime powerd_suspend RTC timestamp saving and make sure hwclock works 140 utils.open_write_close(self.HWCLOCK_FILE, '') 141 hwclock_output = utils.system_output('hwclock -r --verbose --utc', 142 ignore_status=True) 143 if not re.search('Using.*rtc interface to.*clock', hwclock_output): 144 raise error.TestError('hwclock cannot find rtc: ' + hwclock_output) 145 146 # activate device suspend timing debug output 147 if hasattr(self, 'device_times'): 148 if not int(utils.read_one_line('/sys/power/pm_print_times')): 149 self._set_pm_print_times(True) 150 self._reset_pm_print_times = True 151 152 # Shut down 3G to remove its variability from suspend time measurements 153 flim = flimflam.FlimFlam() 154 service = flim.FindCellularService(0) 155 if service: 156 logging.info('Found 3G interface, disconnecting.') 157 start_time = time.time() 158 (success, status) = flim.DisconnectService( 159 service=service, wait_timeout=60) 160 if success: 161 logging.info('3G disconnected successfully.') 162 self.disconnect_3G_time = time.time() - start_time 163 else: 164 logging.error('Could not disconnect: %s.', status) 165 self.disconnect_3G_time = -1 166 167 self._configure_suspend_state() 168 169 170 def _configure_suspend_state(self): 171 """Configure the suspend state as requested.""" 172 if self._suspend_state: 173 available_suspend_states = utils.read_one_line('/sys/power/state') 174 if self._suspend_state not in available_suspend_states: 175 raise error.TestNAError('Invalid suspend state: ' + 176 self._suspend_state) 177 # Check the current state. If it is same as the one requested, 178 # we don't want to call PowerPrefChanger(restarts powerd). 179 if self._suspend_state == power_utils.get_sleep_state(): 180 return 181 should_freeze = '1' if self._suspend_state == 'freeze' else '0' 182 new_prefs = {self._SUSPEND_STATE_PREF_FILE: should_freeze} 183 self._power_pref_changer = power_utils.PowerPrefChanger(new_prefs) 184 185 186 def _set_pm_print_times(self, on): 187 """Enable/disable extra suspend timing output from powerd to syslog.""" 188 if utils.system('echo %s > /sys/power/pm_print_times' % int(bool(on)), 189 ignore_status=True): 190 logging.warning('Failed to set pm_print_times to %s', bool(on)) 191 del self.device_times 192 self._reset_pm_print_times = False 193 else: 194 logging.info('Device resume times set to %s', bool(on)) 195 196 197 def _get_board(self): 198 """Remove _freon from get_board if found.""" 199 return (utils.get_board().replace("_freon", "")) 200 201 202 def _retrive_last_matching_line_ts(self, filename, pattern): 203 """ 204 Returns timestamp of last matching line or None 205 """ 206 with open(filename) as f: 207 lines = f.readlines() 208 for line in reversed(lines): 209 if re.search(pattern, line): 210 matches = re.search(self._POWERD_TS_RE, line) 211 if matches: 212 return matches.group(1) 213 return None 214 215 216 def _aborted_due_to_locking(self): 217 """ 218 Returns true if we found evidences in the powerd log that the suspend 219 was aborted due to power_management override lock. 220 """ 221 latest_ts = self._retrive_last_matching_line_ts( 222 self._POWERD_LOG_LATEST_PATH, self._ABORT_DUE_TO_OVERRIDE_LINE) 223 if latest_ts is None: 224 latest_ts = self._retrive_last_matching_line_ts( 225 self._POWERD_LOG_PREVIOUS_PATH, self._ABORT_DUE_TO_OVERRIDE_LINE) 226 227 if latest_ts is None: 228 return False 229 230 if latest_ts > self._powerd_cycle_start_ts: 231 return True 232 233 return False 234 235 236 def _reset_logs(self): 237 """Throw away cached log lines and reset log pointer to current end.""" 238 if self._log_file: 239 self._log_file.close() 240 self._log_file = open('/var/log/messages') 241 self._log_file.seek(0, os.SEEK_END) 242 self._logs = [] 243 244 self._powerd_cycle_start_ts = ( 245 self._retrive_last_matching_line_ts(self._POWERD_LOG_LATEST_PATH, 246 self._POWERD_TS_RE)) 247 248 249 def _check_resume_finished(self, retries=11): 250 """ 251 Read all lines logged since last reset into log cache. Block until last 252 powerd_suspend resume message was read. Returns true if succeeded or 253 false if took too long 254 """ 255 finished_regex = re.compile(r'powerd_suspend\[\d+\]: Resume finished') 256 for retry in xrange(retries + 1): 257 lines = self._log_file.readlines() 258 if lines: 259 if self._logs and self._logs[-1][-1] != '\n': 260 # Reassemble line that was cut in the middle 261 self._logs[-1] += lines.pop(0) 262 self._logs += lines 263 for line in reversed(self._logs): 264 if (finished_regex.search(line)): 265 return True 266 time.sleep(0.005 * 2**retry) 267 268 return False 269 270 271 def _ts(self, name, retries=11): 272 """Searches logs for last timestamp with a given suspend message.""" 273 # Occasionally need to retry due to races from process wakeup order 274 for retry in xrange(retries + 1): 275 try: 276 f = open(self._TIMINGS_FILE) 277 for line in f: 278 words = line.split('=') 279 if name == words[0]: 280 try: 281 timestamp = float(words[1]) 282 except ValueError: 283 logging.warning('Invalid timestamp: %s', line) 284 timestamp = 0 285 return timestamp 286 except IOError: 287 pass 288 time.sleep(0.005 * 2**retry) 289 290 raise error.TestError('Could not find %s entry.' % name) 291 292 293 def _hwclock_ts(self, not_before): 294 """Read the RTC resume timestamp saved by powerd_suspend.""" 295 early_wakeup = False 296 if os.path.exists(self.HWCLOCK_FILE): 297 # TODO(crbug.com/733773): Still fragile see bug. 298 match = re.search(r'(.+)(\.\d+)[+-]\d+:?\d+$', 299 utils.read_file(self.HWCLOCK_FILE), re.DOTALL) 300 if match: 301 timeval = time.strptime(match.group(1), "%Y-%m-%d %H:%M:%S") 302 seconds = time.mktime(timeval) 303 seconds += float(match.group(2)) 304 logging.debug('RTC resume timestamp read: %f', seconds) 305 if not_before is None or seconds >= not_before: 306 return seconds 307 early_wakeup = True 308 if early_wakeup: 309 logging.debug('Early wakeup, dumping eventlog if it exists:\n') 310 elog = utils.system_output('mosys eventlog list | tail -n %d' % 311 self._RELEVANT_EVENTLOG_LINES, ignore_status=True) 312 wake_elog = (['unknown'] + re.findall(r'Wake Source.*', elog))[-1] 313 for line in reversed(self._logs): 314 match = re.search(r'PM1_STS: WAK.*', line) 315 if match: 316 wake_syslog = match.group(0) 317 break 318 else: 319 wake_syslog = 'unknown' 320 for b, e, s in sys_power.SpuriousWakeupError.S3_ALLOWLIST: 321 if (re.search(b, utils.get_board()) and 322 re.search(e, wake_elog) and re.search(s, wake_syslog)): 323 logging.warning('Allowlisted spurious wake in S3: %s | %s', 324 wake_elog, wake_syslog) 325 return None 326 raise sys_power.SpuriousWakeupError('Spurious wake in S3: %s | %s' 327 % (wake_elog, wake_syslog)) 328 raise error.TestError('Broken RTC timestamp: ' + 329 utils.read_file(self.HWCLOCK_FILE)) 330 331 332 def _firmware_resume_time(self): 333 """Calculate seconds for firmware resume from logged TSC. (x86 only)""" 334 if utils.get_arch() not in ['i686', 'x86_64']: 335 # TODO: support this on ARM somehow 336 return 0 337 regex_freeze = re.compile(r'PM: resume from suspend-to-idle') 338 regex_tsc = re.compile(r'TSC at resume: (\d+)$') 339 freq = 1000 * int(utils.read_one_line( 340 '/sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq')) 341 for line in reversed(self._logs): 342 match_freeze = regex_freeze.search(line) 343 if match_freeze: 344 logging.info('fw resume time zero due to suspend-to-idle\n') 345 return 0 346 match_tsc = regex_tsc.search(line) 347 if match_tsc: 348 return float(match_tsc.group(1)) / freq 349 350 raise error.TestError('Failed to find TSC resume value in syslog.') 351 352 353 def _device_resume_time(self): 354 """Read amount of seconds for overall device resume from syslog.""" 355 regex = re.compile(r'PM: resume of devices complete after ([0-9.]+)') 356 for line in reversed(self._logs): 357 match = regex.search(line) 358 if match: 359 return float(match.group(1)) / 1000 360 361 raise error.TestError('Failed to find device resume time in syslog.') 362 363 364 def _get_phase_times(self): 365 phase_times = [] 366 regex = re.compile(r'PM: (\w+ )?(resume|suspend) of devices complete') 367 for line in self._logs: 368 match = regex.search(line) 369 if match: 370 ts = cros_logging.extract_kernel_timestamp(line) 371 phase = match.group(1) 372 if not phase: 373 phase = 'REG' 374 phase_times.append((phase.upper(), ts)) 375 return sorted(phase_times, key = lambda entry: entry[1]) 376 377 378 def _get_phase(self, ts, phase_table, dev): 379 for entry in phase_table: 380 #checking if timestamp was before that phase's cutoff 381 if ts < entry[1]: 382 return entry[0] 383 raise error.TestError('Device %s has a timestamp after all devices %s', 384 dev, 'had already resumed') 385 386 387 def _individual_device_times(self, start_resume): 388 """Return dict of individual device suspend and resume times.""" 389 self.device_times.append(dict()) 390 dev_details = collections.defaultdict(dict) 391 regex = re.compile(r'call ([^ ]+)\+ returned 0 after ([0-9]+) usecs') 392 phase_table = self._get_phase_times() 393 for line in self._logs: 394 match = regex.search(line) 395 if match: 396 device = match.group(1).replace(':', '-') 397 key = 'seconds_dev_' + device 398 secs = float(match.group(2)) / 1e6 399 ts = cros_logging.extract_kernel_timestamp(line) 400 if ts > start_resume: 401 key += '_resume' 402 else: 403 key += '_suspend' 404 #looking if we're in a special phase 405 phase = self._get_phase(ts, phase_table, device) 406 dev = dev_details[key] 407 if phase in dev: 408 logging.warning('Duplicate %s entry for device %s, +%f', phase, 409 device, secs) 410 dev[phase] += secs 411 else: 412 dev[phase] = secs 413 414 for dev_key, dev in dev_details.iteritems(): 415 total_secs = sum(dev.values()) 416 self.device_times[-1][dev_key] = total_secs 417 report = '%s: %f TOT' % (dev_key, total_secs) 418 for phase in dev.keys(): 419 if phase is 'REG': 420 continue 421 report += ', %f %s' % (dev[phase], phase) 422 logging.debug(report) 423 424 425 def _identify_driver(self, device): 426 """Return the driver name of a device (or "unknown").""" 427 for path, subdirs, _ in os.walk('/sys/devices'): 428 if device in subdirs: 429 node = os.path.join(path, device, 'driver') 430 if not os.path.exists(node): 431 return "unknown" 432 return os.path.basename(os.path.realpath(node)) 433 else: 434 return "unknown" 435 436 437 def _check_for_errors(self, ignore_kernel_warns): 438 """Find and identify suspend errors. 439 440 @param ignore_kernel_warns: Ignore kernel errors. 441 442 @returns: True iff we should retry. 443 444 @raises: 445 sys_power.KernelError: for non-allowlisted kernel failures. 446 sys_power.SuspendTimeout: took too long to enter suspend. 447 sys_power.SpuriousWakeupError: woke too soon from suspend. 448 sys_power.SuspendFailure: unidentified failure. 449 """ 450 warning_regex = re.compile(r' kernel: \[.*WARNING:') 451 abort_regex = re.compile(r' kernel: \[.*Freezing of tasks abort' 452 r'| powerd_suspend\[.*Cancel suspend at kernel' 453 r'| powerd_suspend\[.*Warning: Device or resource busy on ' \ 454 'write to /sys/power/state') 455 # rsyslogd can put this out of order with dmesg, so track in variable 456 fail_regex = re.compile(r'powerd_suspend\[\d+\]: Error') 457 failed = False 458 459 # TODO(scottz): warning_monitor crosbug.com/38092 460 log_len = len(self._logs) 461 for i in xrange(log_len): 462 line = self._logs[i] 463 if warning_regex.search(line): 464 # match the source file from the WARNING line, and the 465 # actual error text by peeking one or two lines below that 466 src = cros_logging.strip_timestamp(line) 467 text = '' 468 if i+1 < log_len: 469 text = cros_logging.strip_timestamp(self._logs[i + 1]) 470 if i+2 < log_len: 471 text += '\n' + cros_logging.strip_timestamp( 472 self._logs[i + 2]) 473 for p1, p2 in sys_power.KernelError.ALLOWLIST: 474 if re.search(p1, src) and re.search(p2, text): 475 logging.info('Allowlisted KernelError: %s', src) 476 break 477 else: 478 if ignore_kernel_warns: 479 logging.warn('Non-allowlisted KernelError: %s', src) 480 else: 481 raise sys_power.KernelError("%s\n%s" % (src, text)) 482 if abort_regex.search(line): 483 wake_source = 'unknown' 484 match = re.search(r'last active wakeup source: (.*)$', 485 '\n'.join(self._logs[i-5:i+3]), re.MULTILINE) 486 if match: 487 wake_source = match.group(1) 488 driver = self._identify_driver(wake_source) 489 for b, w in sys_power.SpuriousWakeupError.S0_ALLOWLIST: 490 if (re.search(b, utils.get_board()) and 491 re.search(w, wake_source)): 492 logging.warning('Allowlisted spurious wake before ' 493 'S3: %s | %s', wake_source, driver) 494 return True 495 if "rtc" in driver: 496 raise sys_power.SuspendTimeout('System took too ' 497 'long to suspend.') 498 raise sys_power.SpuriousWakeupError('Spurious wake ' 499 'before S3: %s | %s' % (wake_source, driver)) 500 if fail_regex.search(line): 501 failed = True 502 503 if failed: 504 raise sys_power.SuspendFailure('Unidentified problem.') 505 return False 506 507 508 def _arc_resume_ts(self, retries=3): 509 """Parse arc logcat for arc resume timestamp. 510 511 @param retries: retry if the expected log cannot be found in logcat. 512 513 @returns: a float representing arc resume timestamp in CPU seconds 514 starting from the last boot if arc logcat resume log is parsed 515 correctly; otherwise None. 516 517 """ 518 command = 'android-sh -c "logcat -v monotonic -t 300 *:silent' \ 519 ' ArcPowerManagerService:D"' 520 regex_resume = re.compile(r'^\s*(\d+\.\d+).*ArcPowerManagerService: ' 521 'Device finished resuming$') 522 for retry in xrange(retries + 1): 523 arc_logcat = utils.system_output(command, ignore_status=False) 524 arc_logcat = arc_logcat.splitlines() 525 for line in arc_logcat: 526 logging.debug('arc_resume: %s', line) 527 match_resume = regex_resume.search(line) 528 # ARC logcat is cleared before suspend so the first ARC resume 529 # timestamp is the one we are looking for. 530 if match_resume: 531 return float(match_resume.group(1)) 532 time.sleep(0.005 * 2**retry) 533 else: 534 logging.error('ARC did not resume correctly.') 535 return None 536 537 538 def get_suspend_delay(self): 539 return self._SUSPEND_DELAY.get(self._get_board(), 540 self._DEFAULT_SUSPEND_DELAY) 541 542 543 def suspend(self, duration=10, ignore_kernel_warns=False, 544 measure_arc=False): 545 """ 546 Do a single suspend for 'duration' seconds. Estimates the amount of time 547 it takes to suspend for a board (see _SUSPEND_DELAY), so the actual RTC 548 wakeup delay will be longer. Returns None on errors, or raises the 549 exception when _throw is set. Returns a dict of general measurements, 550 or a tuple (general_measurements, individual_device_times) when 551 _device_times is set. 552 553 @param duration: time in seconds to do a suspend prior to waking. 554 @param ignore_kernel_warns: Ignore kernel errors. Defaults to false. 555 """ 556 557 if power_utils.get_sleep_state() == 'freeze': 558 arch = utils.get_arch() 559 560 if arch == 'x86_64': 561 self._s0ix_residency_stats = power_status.S0ixResidencyStats() 562 elif arch == 'aarch64': 563 self._s2idle_residency_stats = \ 564 power_status.S2IdleResidencyStats() 565 566 try: 567 iteration = len(self.failures) + len(self.successes) + 1 568 # Retry suspend in case we hit a known (allowlisted) bug 569 for _ in xrange(10): 570 # Clear powerd_suspend RTC timestamp, to avoid stale results. 571 utils.open_write_close(self.HWCLOCK_FILE, '') 572 self._reset_logs() 573 utils.system('sync') 574 board_delay = self.get_suspend_delay() 575 # Clear the ARC logcat to make parsing easier. 576 if measure_arc: 577 command = 'android-sh -c "logcat -c"' 578 utils.system(command, ignore_status=False) 579 try: 580 # Return value of suspend method can be None 581 alarm = self._suspend(duration + board_delay) 582 except sys_power.SpuriousWakeupError: 583 # might be another error, we check for it ourselves below 584 alarm = self._ALARM_FORCE_EARLY_WAKEUP 585 586 log_data = subprocess.check_output(['cbmem', 587 '-1']).decode('utf-8') 588 589 for msg in re.findall(r'^.*ERROR.*$', log_data, re.M): 590 for board, pattern in sys_power.FirmwareError.ALLOWLIST: 591 if (re.search(board, utils.get_board()) 592 and re.search(pattern, msg)): 593 logging.info('Allowlisted FW error: %s', msg) 594 break 595 else: 596 firmware_log = os.path.join(self._logdir, 597 'firmware.log.' + str(iteration)) 598 with open(firmware_log, 'w') as f: 599 f.write(log_data) 600 logging.info('Saved firmware log: %s', 601 firmware_log) 602 603 raise sys_power.FirmwareError( 604 msg.strip('\r\n ')) 605 606 if not self._check_resume_finished(): 607 if not self._aborted_due_to_locking(): 608 raise error.TestError("Sanity check failed: did not try to suspend.") 609 logging.warning('Aborted suspend due to power override, will retry\n') 610 continue 611 if not self._check_for_errors(ignore_kernel_warns): 612 hwclock_ts = self._hwclock_ts(alarm) 613 if hwclock_ts: 614 break 615 616 else: 617 raise error.TestWarn('Ten tries failed due to allowlisted bug') 618 619 # calculate general measurements 620 start_resume = self._ts('start_resume_time') 621 kernel_down = (self._ts('end_suspend_time') - 622 self._ts('start_suspend_time')) 623 kernel_up = self._ts('end_resume_time') - start_resume 624 devices_up = self._device_resume_time() 625 firmware_up = self._firmware_resume_time() 626 # If we do not know the time at which the alarm went off, we cannot 627 # calculate the |total_up| and |board_up| time. 628 if alarm: 629 total_up = hwclock_ts - alarm 630 board_up = total_up - kernel_up - firmware_up 631 else: 632 total_up = -1 633 board_up = -1 634 try: 635 cpu_up = self._ts('cpu_ready_time', 0) - start_resume 636 except error.TestError: 637 # can be missing on non-SMP machines 638 cpu_up = None 639 if total_up > self._MAX_RESUME_TIME: 640 raise error.TestError('Sanity check failed: missed RTC wakeup.') 641 642 logging.info('Success(%d): %g down, %g up, %g board, %g firmware, ' 643 '%g kernel, %g cpu, %g devices', 644 iteration, kernel_down, total_up, board_up, 645 firmware_up, kernel_up, cpu_up, devices_up) 646 647 if hasattr(self, '_s0ix_residency_stats'): 648 s0ix_residency_secs = \ 649 self._s0ix_residency_stats.\ 650 get_accumulated_residency_secs() 651 cpu_uarch = utils.get_intel_cpu_uarch() 652 if not s0ix_residency_secs: 653 msg = 'S0ix residency did not change.' 654 if cpu_uarch not in self._IGNORE_S0IX_RESIDENCY_CHECK: 655 raise sys_power.S0ixResidencyNotChanged(msg) 656 logging.warn(msg) 657 logging.info('S0ix residency : %d secs.', s0ix_residency_secs) 658 elif hasattr(self, '_s2idle_residency_stats'): 659 s2idle_residency_usecs = \ 660 self._s2idle_residency_stats.\ 661 get_accumulated_residency_usecs() 662 if not s2idle_residency_usecs: 663 msg = 's2idle residency did not change.' 664 raise sys_power.S2IdleResidencyNotChanged(msg) 665 666 logging.info('s2idle residency : %d usecs.', 667 s2idle_residency_usecs) 668 669 successful_suspend = { 670 'seconds_system_suspend': kernel_down, 671 'seconds_system_resume': total_up, 672 'seconds_system_resume_firmware': firmware_up + board_up, 673 'seconds_system_resume_firmware_cpu': firmware_up, 674 'seconds_system_resume_firmware_ec': board_up, 675 'seconds_system_resume_kernel': kernel_up, 676 'seconds_system_resume_kernel_cpu': cpu_up, 677 'seconds_system_resume_kernel_dev': devices_up, 678 } 679 680 if measure_arc: 681 arc_resume_ts = self._arc_resume_ts() 682 if arc_resume_ts: 683 successful_suspend['seconds_system_resume_arc'] = \ 684 arc_resume_ts - start_resume 685 686 self.successes.append(successful_suspend) 687 688 if hasattr(self, 'device_times'): 689 self._individual_device_times(start_resume) 690 return (self.successes[-1], self.device_times[-1]) 691 else: 692 return self.successes[-1] 693 694 except sys_power.SuspendFailure as ex: 695 message = '%s(%d): %s' % (type(ex).__name__, iteration, ex) 696 logging.error(message) 697 self.failures.append(ex) 698 if self._throw: 699 if type(ex).__name__ in ['KernelError', 'SuspendTimeout']: 700 raise error.TestWarn(message) 701 else: 702 raise error.TestFail(message) 703 return None 704 705 706 def finalize(self): 707 """Restore normal environment (not turning 3G back on for now...)""" 708 if os.path.exists(self.HWCLOCK_FILE): 709 os.remove(self.HWCLOCK_FILE) 710 if self._restart_tlsdated: 711 utils.system('initctl start tlsdated') 712 if self._reset_pm_print_times: 713 self._set_pm_print_times(False) 714 if hasattr(self, '_power_pref_changer'): 715 self._power_pref_changer.finalize() 716 717 718 def __del__(self): 719 self.finalize() 720