| # Copyright (c) 2010 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 commands, logging, random, re, time |
| from autotest_lib.client.bin import test, utils |
| from autotest_lib.client.common_lib import error |
| from autotest_lib.client.cros import rtc, sys_power, cros_logging |
| |
| from autotest_lib.client.cros import flimflam_test_path |
| import flimflam |
| |
| |
| # TODO(cychiang/jsalz): Use cros.factory.goofy.time_sanitizer.CheckHwclock. |
| def CheckHwclock(): |
| '''Check hwclock is working by a write(retry once if fail) and a read.''' |
| for _ in xrange(2): |
| logging.info('Setting hwclock') |
| if utils.system('hwclock -w --utc --noadjfile', ignore_status=True) == 0: |
| break |
| else: |
| logging.error('Unable to set hwclock time') |
| |
| logging.info('Current hwclock time: %s' % |
| utils.system_output('hwclock -r')) |
| |
| |
| class power_Resume(test.test): |
| version = 1 |
| preserve_srcdir = True |
| |
| |
| def _get_key_name_from_dev_name(self, key_name): |
| """Transform a string in such a way that it will be accepted by |
| autotest framework as a key. |
| |
| A device name will contain ':' and '+'. Autotest doesn't allows these |
| characters in the key. |
| |
| Args: |
| key_name: The string that it will be transformed. |
| |
| Return: |
| A new string that autotest will accept as a key name. |
| """ |
| |
| return key_name.replace(':', '-').replace('+', '_') |
| |
| |
| def _get_sr_time_for_each_device(self, sus_time, res_time): |
| """Get how much time each device took to suspend/resume in a certain |
| interval. |
| |
| Args: |
| sus_time: The time interval for suspend messages (in dmesg |
| timestamps) described as a tuple. Where sus_time[0] is the |
| start of the interval and sus_time[1] is the end of the |
| interval. If the interval is badly specified (i.e. |
| sus_time[0] > sus_time[1]) then no suspend message is |
| extracted/parsed and a warning is logged. |
| res_time: The time interval for resume messages (in dmesg |
| timestamps) described as a tuple. Similar format as |
| sus_time argument. |
| |
| Return: |
| A dictionary with the following key format: |
| seconds_dev_<devname>_<action>. Where <devname> is the name of |
| the device (escaped in such a way that autotest will accept the |
| string as key) and <action> one of the following strings: |
| 'resume' or 'suspend'. The value is the number of seconds (as a |
| float) that it took for <devname> to do a suspend or a resume. |
| |
| Raise: |
| TestError: If the log is corrupted. |
| """ |
| |
| sr_time = {} |
| call_regexp = re.compile(r'call ([^ ]+) returned 0 after ([0-9]+) ' |
| 'usecs') |
| |
| if sus_time[0] > sus_time[1]: |
| logging.error("Suspend interval is wrong.") |
| |
| if res_time[0] > res_time[1]: |
| logging.error("Resume interval is wrong.") |
| |
| for dev_line in self._log_msg.get_logs().splitlines(): |
| # find the time stamp for each message |
| ts = -1 |
| try: |
| ts = cros_logging.extract_kernel_timestamp(dev_line) |
| except error.TestError: |
| # probabily not an interesting message |
| continue |
| |
| is_suspend = None |
| |
| if ts >= sus_time[0] and ts <= sus_time[1]: |
| is_suspend = True |
| |
| if ts >= res_time[0] and ts <= res_time[1]: |
| is_suspend = False |
| |
| if is_suspend is None: |
| # skip this message, because it's in a different interval |
| continue |
| |
| # extract the device name and device time |
| search_groups = call_regexp.search(dev_line) |
| |
| if search_groups is None: |
| # this line doesn't contains a call string |
| continue |
| |
| (device_name, time_matched) = search_groups.groups() |
| device_time = float(time_matched) |
| |
| action = 'suspend' if is_suspend else 'resume' |
| |
| # convert from usec to seconds and save the result |
| device_name_key = 'seconds_dev_' + \ |
| self._get_key_name_from_dev_name(device_name) + '_' + action |
| |
| if sr_time.has_key(device_name_key): |
| logging.warn("Duplicate entry for %s (%s)." % |
| (device_name, action)) |
| |
| sr_time[device_name_key] = device_time / 1e6 |
| |
| logging.debug("%s = %s", device_name_key, sr_time[device_name_key]) |
| |
| return sr_time |
| |
| |
| def _get_last_msg(self, patterns): |
| return self._log_msg.get_last_msg(patterns, |
| retries=5, sleep_seconds=1) |
| |
| |
| def _get_last_msg_time(self, patterns): |
| """Extract timestamp from a message which matches a certain pattern(s). |
| |
| Args: |
| patterns: Pattern or list of patterns that the message will match. |
| |
| Returns: |
| The timestamp from the last matched message or -1 if we couldn't |
| match a message. |
| |
| Raises: |
| TestError: If the timestamp could not be extracted from the matched |
| pattern. |
| """ |
| msg = self._get_last_msg(patterns) |
| |
| if msg is None: |
| # we didn't find the pattern |
| return -1 |
| else: |
| return cros_logging.extract_kernel_timestamp(msg) |
| |
| |
| def _get_end_cpu_resume_time(self): |
| # systems with only one logical CPU won't have this message, return -1 |
| time = self._get_last_msg_time('CPU[0-9]+ is up') |
| logging.debug('END cpu resume time %f' % time) |
| |
| return time |
| |
| |
| def _get_start_suspend_time(self): |
| time = self._get_last_msg_time( |
| sys_power.SUSPEND_RESUME_MESSAGES['START_SUSPEND']) |
| if time == -1: |
| raise error.TestError("Could not find start suspend time message.") |
| logging.debug('START suspend time: %f' % time) |
| |
| return time |
| |
| |
| def _get_end_suspend_time(self): |
| time = self._get_last_msg_time( |
| sys_power.SUSPEND_RESUME_MESSAGES['END_SUSPEND']) |
| if time == -1: |
| raise error.TestError("Could not find end suspend time message.") |
| logging.debug('END suspend time %f' % time) |
| |
| return time |
| |
| |
| def _get_start_resume_time(self): |
| time = self._get_last_msg_time( |
| sys_power.SUSPEND_RESUME_MESSAGES['START_RESUME']) |
| if time == -1: |
| raise error.TestError("Could not find start resume time message.") |
| logging.debug('START resume time %f' % time) |
| |
| return time |
| |
| |
| def _get_end_resume_time(self): |
| time = self._get_last_msg_time( |
| sys_power.SUSPEND_RESUME_MESSAGES['END_RESUME']) |
| if time == -1: |
| raise error.TestError("Could not find end resume time message.") |
| logging.debug('END resume time %f' % time) |
| |
| return time |
| |
| |
| def _get_device_resume_time(self): |
| data = self._get_last_msg("PM: resume of devices complete after") |
| match = re.search(r'PM: resume of devices complete after ([0-9.]+)', |
| data) |
| if match is None: |
| raise error.TestError('Failed to find device resume time on line: ' |
| + data) |
| logging.debug('device resume time: %f' % (float(match.group(1))/1e3)) |
| |
| # convert from msec to sec |
| return float(match.group(1)) / 1000 |
| |
| |
| def _get_hwclock_seconds(self): |
| """ |
| Read the hwclock resume time saved off by powerd_resume |
| """ |
| count = 0 |
| while count < 5: |
| hwclock_output = utils.read_file('/var/run/power_manager/'+ |
| 'hwclock-on-resume') |
| logging.debug('hwclock_output: ' + hwclock_output) |
| match = re.search( |
| r'= ([0-9]+) seconds since .+ (-?[0-9.]+) seconds$', |
| hwclock_output, re.DOTALL) |
| if match: |
| seconds = int(match.group(1)) + float(match.group(2)) |
| logging.debug('hwclock seconds = %f' % seconds) |
| return seconds |
| |
| # hwclock-on-resume file doesn't contain valid data. Retry |
| count += 1 |
| time.sleep(1) |
| |
| raise ValueError('Unable to read the hardware clock -- ' + |
| hwclock_output) |
| |
| |
| def _set_pm_print_times(self, enabled): |
| cmd = 'echo %s > /sys/power/pm_print_times' % int(bool(enabled)) |
| (status, output) = commands.getstatusoutput(cmd) |
| if status != 0: |
| logging.warn('Failed to set pm_print_times to %s' % bool(enabled)) |
| else: |
| logging.info('Device resume times set to %s' % bool(enabled)) |
| |
| |
| def _enable_pm_print_times(self): |
| self._set_pm_print_times(True) |
| |
| |
| def _disable_pm_print_times(self): |
| self._set_pm_print_times(False) |
| |
| |
| def run_once(self, max_devs_returned=10): |
| # Check hwclock is working |
| CheckHwclock() |
| |
| # Disconnect from 3G network to take out the variability of |
| # disconnection time from suspend_time |
| disconnect_3G_time = 0 |
| flim = flimflam.FlimFlam() |
| service = flim.FindCellularService() |
| if service: |
| logging.info('Found 3G interface, disconnecting.') |
| start_time = time.time() |
| success, status = flim.DisconnectService( |
| service=service, |
| wait_timeout=60) |
| disconnect_3G_time = time.time() - start_time |
| if success: |
| logging.info('3G disconnected successfully.') |
| else: |
| logging.error('Could not disconnect: %s.' % status) |
| disconnect_3G_time = -1 |
| |
| self._enable_pm_print_times() |
| # Some idle time before initiating suspend-to-ram |
| idle_time = random.randint(1, 10) |
| time.sleep(idle_time) |
| |
| # Safe enough number, can tweek if necessary |
| time_to_sleep = 10 |
| |
| sr_time_for_devs = {} |
| |
| # Keep trying the suspend/resume several times to get all positive |
| # time readings. |
| max_num_attempts = 5 |
| for retry_count in range(max_num_attempts): |
| # Set the alarm |
| alarm_time = rtc.get_seconds() + time_to_sleep |
| logging.debug('alarm_time = %d', alarm_time) |
| rtc.set_wake_alarm(alarm_time) |
| |
| # Suspend the system to RAM |
| sys_power.suspend_to_ram() |
| |
| # initialize LogReader object |
| self._log_msg = \ |
| cros_logging.LogReader(include_rotated_logs=False) |
| |
| # Get suspend and resume times from /var/log/messages |
| start_suspend_time = self._get_start_suspend_time() |
| end_suspend_time = self._get_end_suspend_time() |
| start_resume_time = self._get_start_resume_time() |
| end_resume_time = self._get_end_resume_time() |
| end_cpu_resume_time = self._get_end_cpu_resume_time() |
| kernel_device_resume_time = self._get_device_resume_time() |
| |
| sr_time_for_devs = \ |
| self._get_sr_time_for_each_device( |
| (start_suspend_time, end_suspend_time), |
| (start_resume_time, end_resume_time)) |
| |
| # Calculate the suspend/resume times |
| total_resume_time = self._get_hwclock_seconds() - alarm_time |
| suspend_time = end_suspend_time - start_suspend_time |
| kernel_resume_time = end_resume_time - start_resume_time |
| |
| kernel_cpu_resume_time = 0 |
| if end_cpu_resume_time > 0: |
| kernel_cpu_resume_time = end_cpu_resume_time - start_resume_time |
| |
| firmware_resume_time = total_resume_time - kernel_resume_time |
| |
| # If the values all came out to be nonnegative, it means success, so |
| # exit the retry loop. |
| if suspend_time >= 0 and total_resume_time >= 0 and \ |
| firmware_resume_time >= 0: |
| break |
| |
| # Flag an error if the max attempts have been reached without a set |
| # of successful result values. |
| if retry_count >= max_num_attempts - 1: |
| raise error.TestError( \ |
| "Negative time results, exceeded max retries.") |
| |
| # Prepare the results |
| results = {} |
| |
| # return as keyvals the slowest n devices |
| slowest_devs = sorted( |
| sr_time_for_devs, |
| key=sr_time_for_devs.get, |
| reverse=True)[:max_devs_returned] |
| for dev in slowest_devs: |
| results[dev] = sr_time_for_devs[dev] |
| |
| results['seconds_system_suspend'] = suspend_time |
| results['seconds_system_resume'] = total_resume_time |
| results['seconds_system_resume_firmware'] = firmware_resume_time |
| results['seconds_system_resume_kernel'] = kernel_resume_time |
| results['seconds_system_resume_kernel_cpu'] = kernel_cpu_resume_time |
| results['seconds_system_resume_kernel_dev'] = kernel_device_resume_time |
| results['seconds_3G_disconnect'] = disconnect_3G_time |
| results['num_retry_attempts'] = retry_count |
| |
| self.write_perf_keyval(results) |
| |
| |
| def cleanup(self): |
| self._disable_pm_print_times() |
