| # Copyright (c) 2012 The Chromium OS Authors. All rights reserved. |
| # Use of this source code is governed by a BSD-style license that can be |
| # found in the LICENSE file. |
| |
| import logging, os, re, time |
| |
| import common |
| from autotest_lib.client.bin import utils |
| from autotest_lib.client.common_lib import error, enum |
| from autotest_lib.client.cros import cros_logging, rtc, sys_power |
| from autotest_lib.client.cros import flimflam_test_path |
| import flimflam |
| |
| |
| class SuspendFailure(error.TestFail): |
| """Base class for a failure during a single suspend/resume cycle.""" |
| pass |
| |
| |
| class SuspendAbort(SuspendFailure): |
| """Suspend took too long, got wakeup event (RTC tick) before it was done.""" |
| pass |
| |
| |
| class HwClockError(SuspendFailure): |
| """Known bug with firmware messing up RTC interrupts (crosbug.com/36004)""" |
| AFFECTED_BOARDS = ['LUMPY', 'STUMPY', 'KIEV'] |
| @staticmethod |
| def is_affected(): |
| """Returns True iff the current board is known to be affected.""" |
| return utils.get_board() in HwClockError.AFFECTED_BOARDS |
| |
| |
| class FirmwareError(SuspendFailure): |
| """String 'ERROR' found in firmware log after resume.""" |
| WHITELIST = [r'PNP: 002e\.4 70 irq size: 0x0000000001 not assigned'] |
| |
| |
| class KernelError(SuspendFailure): |
| """Kernel WARN_ON() hit during suspend/resume.""" |
| pass |
| |
| |
| class Suspender(object): |
| """Class for suspend/resume measurements. |
| |
| Public attributes: |
| disconnect_3G_time: Amount of seconds it took to disable 3G. |
| successes[]: List of timing measurement dicts from successful suspends. |
| failures[]: List of SuspendFailure exceptions from failed suspends. |
| device_times[]: List of individual device suspend/resume time dicts. |
| |
| Public methods: |
| suspend: Do a suspend/resume cycle. Return timing measurement dict. |
| |
| Private attributes: |
| _log_reader: LogReader that is set to start right before suspending. |
| _use_dbus: Set to use asynchronous DBus method for suspending. |
| _throw: Set to have SuspendFailure exceptions raised to the caller. |
| _reset_pm_print_times: Set to deactivate pm_print_times after the test. |
| _restart_tlsdated: Set to restart tlsdated after the test. |
| |
| Private methods: |
| __init__: Shuts off tlsdated for duration of test, disables 3G |
| __del__: Restore tlsdated (must run eventually, but GC delay no problem) |
| _set_pm_print_times: Enable/disable kernel device suspend timing output. |
| _check_failure_log: Check /sys/.../suspend_stats for new failures. |
| _ts: Returns a timestamp from /var/run/power_manager/last_resume_timings |
| _hwclock_ts: Read RTC timestamp left on resume in hwclock-on-resume |
| _device_resume_time: Read seconds overall device resume took from logs. |
| _individual_device_times: Reads individual device suspend/resume times. |
| """ |
| def __init__(self, use_dbus=False, throw=False, device_times=False): |
| """Prepare environment for suspending.""" |
| self.disconnect_3G_time = 0 |
| self.successes = [] |
| self.failures = [] |
| self._use_dbus = use_dbus |
| self._throw = throw |
| self._reset_pm_print_times = False |
| self._restart_tlsdated = False |
| self._log_reader = cros_logging.LogReader() |
| if device_times: |
| self.device_times = [] |
| |
| # stop tlsdated, make sure we/hwclock have /dev/rtc for ourselves |
| if utils.system_output('initctl status tlsdated').find('start') != -1: |
| utils.system('initctl stop tlsdated') |
| self._restart_tlsdated = True |
| |
| # prime powerd_suspend RTC timestamp saving and make sure hwclock works |
| utils.open_write_close('/var/run/power_manager/hwclock-on-resume', '') |
| hwclock_output = utils.system_output('hwclock -r --debug --utc', |
| ignore_status=True) |
| if hwclock_output.find('Using /dev interface') == -1: |
| raise error.TestError('hwclock cannot find rtc: ' + hwclock_output) |
| |
| # activate device suspend timing debug output |
| if hasattr(self, 'device_times'): |
| if not int(utils.read_one_line('/sys/power/pm_print_times')): |
| self._set_pm_print_times(True) |
| self._reset_pm_print_times = True |
| |
| # Shut down 3G to remove its variability from suspend time measurements |
| flim = flimflam.FlimFlam() |
| service = flim.FindCellularService(0) |
| if service: |
| logging.info('Found 3G interface, disconnecting.') |
| start_time = time.time() |
| (success, status) = flim.DisconnectService( |
| service=service, wait_timeout=60) |
| if success: |
| logging.info('3G disconnected successfully.') |
| self.disconnect_3G_time = time.time() - start_time |
| else: |
| logging.error('Could not disconnect: %s.' % status) |
| self.disconnect_3G_time = -1 |
| |
| |
| def __del__(self): |
| """Restore normal environment (not turning 3G back on for now...)""" |
| os.remove('/var/run/power_manager/hwclock-on-resume') |
| if self._restart_tlsdated: |
| utils.system('initctl start tlsdated') |
| if self._reset_pm_print_times: |
| self._set_pm_print_times(False) |
| |
| |
| def _set_pm_print_times(self, on): |
| """Enable/disable extra suspend timing output from powerd to syslog.""" |
| if utils.system('echo %s > /sys/power/pm_print_times' % int(bool(on)), |
| ignore_status=True): |
| logging.warn('Failed to set pm_print_times to %s' % bool(on)) |
| del self.device_times |
| self._reset_pm_print_times = False |
| else: |
| logging.info('Device resume times set to %s' % bool(on)) |
| |
| |
| def _ts(self, name, retries=50, sleep_seconds=0.2): |
| """Searches logs for last timestamp with a given suspend message.""" |
| # Occasionally need to retry due to races from process wakeup order |
| for retry in xrange(retries + 1): |
| try: |
| f = open('/var/run/power_manager/last_resume_timings') |
| for line in f: |
| words = line.split('=') |
| if name == words[0]: |
| return float(words[1]); |
| except IOError: |
| pass |
| time.sleep(sleep_seconds) |
| |
| raise error.TestError('Could not find %s entry.' % name) |
| |
| |
| def _hwclock_ts(self, not_before, retries=3): |
| """Read the RTC resume timestamp saved by powerd_suspend.""" |
| path = '/var/run/power_manager/hwclock-on-resume' |
| for _ in xrange(retries + 1): |
| if os.path.exists(path): |
| match = re.search(r'([0-9]+) seconds since .+ (-?[0-9.]+) sec', |
| utils.read_file(path), re.DOTALL) |
| if match: |
| seconds = int(match.group(1)) + float(match.group(2)) |
| if seconds < not_before: continue |
| logging.debug('RTC resume timestamp read: %f' % seconds) |
| return seconds |
| time.sleep(0.2) |
| logging.debug('HwClock failure, dumping nvram:\n' + |
| utils.system_output('mosys nvram dump', ignore_status=True)) |
| raise HwClockError('RTC timestamp broken:' + utils.read_file(path)) |
| |
| |
| def _firmware_resume_time(self): |
| """Calculate seconds for firmware resume from logged TSC. (x86 only)""" |
| if utils.get_arch() not in ['i686', 'x86_64']: |
| # TODO: support this on ARM somehow |
| return 0 |
| pattern = r'TSC at resume: (\d+)$' |
| line = self._log_reader.get_last_msg(pattern) |
| if line: |
| freq = 1000 * int(utils.read_one_line( |
| '/sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq')) |
| return float(re.search(pattern, line).group(1)) / freq |
| raise error.TestError('Failed to find TSC resume value in syslog.') |
| |
| |
| def _device_resume_time(self): |
| """Read amount of seconds for overall device resume from syslog.""" |
| pattern = r'PM: resume of devices complete after ([0-9.]+)' |
| line = self._log_reader.get_last_msg(pattern) |
| if line: |
| return float(re.search(pattern, line).group(1)) / 1000 |
| raise error.TestError('Failed to find device resume time in syslog.') |
| |
| |
| def _individual_device_times(self, start_resume): |
| """Return dict of individual device suspend and resume times.""" |
| self.device_times.append(dict()) |
| regex = re.compile(r'call ([^ ]+)\+ returned 0 after ([0-9]+) usecs') |
| for line in self._log_reader.read_all_logs(): |
| match = regex.search(line) |
| if match: |
| key = 'seconds_dev_' + match.group(1).replace(':', '-') |
| secs = float(match.group(2)) / 1e6 |
| if cros_logging.extract_kernel_timestamp(line) > start_resume: |
| key += '_resume' |
| else: |
| key += '_suspend' |
| if key in self.device_times[-1]: |
| logging.warn('Duplicate entry for %s: +%f' % (key, secs)) |
| self.device_times[-1][key] += secs |
| else: |
| logging.debug('%s: %f' % (key, secs)) |
| self.device_times[-1][key] = secs |
| |
| |
| def suspend(self, duration=10): |
| """ |
| Do a single suspend for 'duration' seconds. Returns None on errors, or |
| raises the exception when _throw is set. Returns a dict of general |
| measurements, or a tuple (general_measurements, individual_device_times) |
| when _device_times is set. |
| """ |
| iteration = len(self.failures) + len(self.successes) + 1 |
| self._log_reader.set_start_by_current() |
| # Remove previous last_run_timings file to prevent races |
| try: |
| os.remove('/var/run/power_manager/last_resume_timings') |
| except OSError: |
| pass |
| try: |
| # set the RTC alarm |
| alarm_time = int(rtc.get_seconds() + duration) |
| logging.debug('Trying suspend %d for %d seconds... wakealarm = %d' % |
| (iteration, duration, alarm_time)) |
| rtc.set_wake_alarm(alarm_time) |
| if len(rtc.get_rtc_devices()) > 1: |
| backup_wake = rtc.get_seconds(rtc_device='rtc1') + duration + 30 |
| logging.debug('Priming backup RTC at %d' % backup_wake) |
| rtc.set_wake_alarm(backup_wake, rtc_device='rtc1') |
| |
| # do the actual suspend |
| if self._use_dbus: |
| # asynch suspend, need to wait a while for it to happen... |
| sys_power.request_suspend() |
| # TODO: replace sleep with listening for DBus resume message |
| time.sleep(3) |
| else: |
| sys_power.write_wakeup_count(sys_power.read_wakeup_count()) |
| sys_power.suspend_to_ram() |
| |
| # look for errors |
| if os.path.exists('/sys/firmware/log'): |
| for msg in re.findall(r'^.*ERROR.*$', |
| utils.read_file('/sys/firmware/log'), re.M): |
| for pattern in FirmwareError.WHITELIST: |
| if re.search(pattern, msg): |
| logging.info('Whitelisted firmware error: ' + msg) |
| break |
| else: |
| raise FirmwareError(msg.strip('\r\n ')) |
| |
| warning_regex = re.compile(r' kernel: \[.*WARNING:') |
| abort_regex = re.compile(r' kernel: \[.*Freezing of tasks aborted|' |
| r'powerd_suspend\[.*Aborting suspend, wake event received') |
| unknown_regex = re.compile(r'powerd_suspend\[\d+\]: Error') |
| for line in self._log_reader.read_all_logs(): |
| if warning_regex.search(line): |
| raise KernelError(line) |
| if abort_regex.search(line): |
| raise SuspendAbort(line) |
| if unknown_regex.search(line): |
| raise SuspendFailure('Unidentified suspend failure.') |
| |
| # calculate general measurements |
| start_resume = self._ts('start_resume_time') |
| kernel_down = (self._ts('end_suspend_time') - |
| self._ts('start_suspend_time')) |
| kernel_up = self._ts('end_resume_time') - start_resume |
| devices_up = self._device_resume_time() |
| total_up = self._hwclock_ts(alarm_time) - alarm_time |
| firmware_up = self._firmware_resume_time() |
| board_up = total_up - kernel_up - firmware_up |
| try: |
| cpu_up = self._ts('cpu_ready_time', 0) - start_resume |
| except error.TestError: |
| # can be missing on non-SMP machines |
| cpu_up = None |
| if total_up > 15: |
| raise SuspendFailure('Duration too short, backup RTC fired!') |
| |
| logging.debug('Success(%d): %g down, %g up, %g board, %g firmware, ' |
| '%g kernel, %g cpu, %g devices' % |
| (iteration, kernel_down, total_up, board_up, |
| firmware_up, kernel_up, cpu_up, devices_up)) |
| self.successes.append({ |
| 'seconds_system_suspend': kernel_down, |
| 'seconds_system_resume': total_up, |
| 'seconds_system_resume_firmware': firmware_up + board_up, |
| 'seconds_system_resume_firmware_cpu': firmware_up, |
| 'seconds_system_resume_firmware_ec': board_up, |
| 'seconds_system_resume_kernel': kernel_up, |
| 'seconds_system_resume_kernel_cpu': cpu_up, |
| 'seconds_system_resume_kernel_dev': devices_up, |
| }) |
| |
| if hasattr(self, 'device_times'): |
| self._individual_device_times(start_resume) |
| return (self.successes[-1], self.device_times[-1]) |
| else: |
| return self.successes[-1] |
| |
| except SuspendFailure as ex: |
| logging.error('%s(%d): %s' % (type(ex).__name__, iteration, ex)) |
| self.failures.append(ex) |
| if self._throw: raise |
| return None |
