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