def _test_wol_magic_packet(self): """Check the Wake-on-LAN (WOL) magic packet capabilities of a device. Raises: error.TestError if WOL functionality fails """ # Magic number WOL supported capname = 'Supports Wake-on' if self._caps[capname][0].find('g') != -1: logging.info("%s support magic number WOL", self._ethname) else: raise error.TestError('%s should support magic number WOL' % self._ethname) # Check that WOL works if self._caps['Wake-on'][0] != 'g': utils.system_output("ethtool -s %s wol g" % self._ethname) self._restore_wol = True # Set RTC as backup to WOL before_secs = rtc.get_seconds() alarm_secs = before_secs + self._suspend_secs + self._threshold_secs rtc.set_wake_alarm(alarm_secs) sys_power.do_suspend(self._suspend_secs) after_secs = rtc.get_seconds() # flush RTC as it may not work subsequently if wake was not RTC rtc.set_wake_alarm(0) suspended_secs = after_secs - before_secs if suspended_secs >= (self._suspend_secs + self._threshold_secs): raise error.TestError("Device woke due to RTC not WOL")
def suspend_and_resume(self, seconds=MIN_SLEEP_INTERVAL): """Suspends for N seconds.""" sleep_seconds = min(seconds, MIN_SLEEP_INTERVAL) suspend_time = rtc.get_seconds() sys_power.do_suspend(sleep_seconds) logging.debug('and we\'re back... %ds elapsed.', rtc.get_seconds() - suspend_time)
def kernel_suspend(seconds, state='mem'): """Do a kernel suspend. Suspend the system to @state, waking up again after |seconds|, by directly writing to /sys/power/state. Function will block until suspend/resume has completed or failed. @param seconds: The number of seconds to suspend the device. @param state: power state to suspend to. DEFAULT mem. """ alarm, wakeup_count = prepare_wakeup(seconds) logging.debug('Saving wakeup count: %d', wakeup_count) write_wakeup_count(wakeup_count) try: logging.info('Suspending at %d', rtc.get_seconds()) with open(SYSFS_POWER_STATE, 'w') as sysfs_file: sysfs_file.write(state) except IOError as e: logging.exception('Writing to %s failed', SYSFS_POWER_STATE) if e.errno == errno.EBUSY and rtc.get_seconds() >= alarm: # The kernel returns EBUSY if it has to abort because # another wakeup fires before we've reached suspend. raise SpuriousWakeupError('Received spurious wakeup in kernel.') else: # Some driver probably failed to suspend properly. # A hint as to what failed is in errno. raise KernelError('Suspend failed: %s' % e.strerror) else: logging.info('Woke from suspend at %d', rtc.get_seconds()) logging.debug('New wakeup count: %d', read_wakeup_count()) check_wakeup(alarm)
def run_once(self, run_time_sec=60): if run_time_sec < 10: raise error.TestFail('Must run for at least 10 seconds') with chrome.Chrome(): # Audio loop time should be significantly shorter than # |run_time_sec| time, so that the total playback time doesn't # exceed it by much. audio_loop_time_sec = min(10, run_time_sec / 10 + 0.5) # Set a low audio volume to avoid annoying people during tests. audio_helper.set_volume_levels(10, 100) # Start playing audio file. self._enable_audio_playback = True thread = threading.Thread(target=self._play_audio, args=(audio_loop_time_sec, )) thread.start() # Restart powerd with timeouts for quick idle events. gap_ms = run_time_sec * 1000 / 4 dim_ms = min(10000, gap_ms) off_ms = min(20000, gap_ms * 2) suspend_ms = min(30000, gap_ms * 3) prefs = { 'disable_idle_suspend': 0, 'ignore_external_policy': 1, 'plugged_dim_ms': dim_ms, 'plugged_off_ms': off_ms, 'plugged_suspend_ms': suspend_ms, 'unplugged_dim_ms': dim_ms, 'unplugged_off_ms': off_ms, 'unplugged_suspend_ms': suspend_ms } self._pref_change = power_utils.PowerPrefChanger(prefs) # Set an alarm to wake up the system in case the audio detector # fails and the system suspends. alarm_time = rtc.get_seconds() + run_time_sec rtc.set_wake_alarm(alarm_time) time.sleep(run_time_sec) # Stop powerd to avoid suspending when the audio stops. utils.system_output('stop powerd') # Stop audio and wait for the audio thread to terminate. self._enable_audio_playback = False thread.join(timeout=(audio_loop_time_sec * 2)) if thread.is_alive(): logging.error('Audio thread did not terminate at end of test.') # Check powerd's log to make sure that no suspend took place. powerd_log_path = '/var/log/power_manager/powerd.LATEST' log = open(powerd_log_path, 'r').read() if log.find('Starting suspend') != -1: err_str = 'System suspended while audio was playing.' raise error.TestFail(err_str)
def check_wakeup(alarm): """Verify that the device did not wakeup early. @param alarm: The time at which the device was expected to wake up. """ now = rtc.get_seconds() if now < alarm: logging.error('Woke up early at %d', now) raise SpuriousWakeupError('Woke from suspend early')
def run_once(self, reachable=None, wifi_timeout=5, dev=None): '''Check that WiFi is working after a resume If test is successful, the performance key "secs_iface_up_delay" is reported as seconds the interface needed to be up @param reachable: ip address (string) to try to ping as a network test @param dev: device (eg 'wlan0') to use for wifi tests. autodetected if unset @param wifi_timeout: number of seconds with in which a WiFi association must be (re)established after a suspend/resume cycle ''' if not dev: dev = get_wifi_dev() if not dev: raise error.TestError('No WiFi device found') logging.info('checking wifi interface %s', dev) check_wifi_dev(dev) if network_is_up(reachable=reachable, dev=dev): suspend_to_ram() start = rtc.get_seconds() deadline = start + wifi_timeout have_network = network_is_up(reachable=reachable, dev=dev) while (not have_network) and (deadline > rtc.get_seconds()): have_network = network_is_up(reachable=reachable, dev=dev) if have_network: delay = rtc.get_seconds() - start logging.info('Network came up at %d seconds', delay) self.write_perf_keyval({'secs_iface_up_delay': delay}) return delay = rtc.get_seconds() - start raise error.TestFail('Network down after %d seconds' % delay) raise error.TestFail('Network down at start of test - cannot continue')
def prepare_wakeup(seconds): """Prepare the device to wake up from an upcoming suspend. @param seconds: The number of seconds to allow the device to suspend. """ # May cause DUT not wake from sleep if the suspend time is 1 second. # It happens when the current clock (floating point) is close to the # next integer, as the RTC sysfs interface only accepts integers. # Make sure it is larger than or equal to 2. assert seconds >= 2 wakeup_count = read_wakeup_count() alarm = int(rtc.get_seconds() + seconds) logging.debug('Suspend for %d seconds, wakealarm = %d', seconds, alarm) rtc.set_wake_alarm(alarm) return (alarm, wakeup_count)
def idle_suspend(seconds): """ Wait for the system to suspend to RAM (S3), scheduling the RTC to wake up |seconds| after this function was called. Caller must ensure that the system will idle-suspend in time for this to happen. Returns the wake alarm time from the RTC as epoch. @param seconds: The number of seconds before wakeup. """ alarm, _ = prepare_wakeup(seconds) while rtc.get_seconds() < alarm: time.sleep(0.2) # tell powerd something happened, or it will immediately idle-suspend again # TODO: switch to cros.power_utils#call_powerd_dbus_method once this # horrible mess with the WiFi tests and this file's imports is solved logging.debug('Simulating user activity after idle suspend...') os.system('dbus-send --type=method_call --system ' '--dest=org.chromium.PowerManager /org/chromium/PowerManager ' 'org.chromium.PowerManager.HandleUserActivity') return alarm
def run_once(self, run_time_sec=60): if run_time_sec < 10: raise error.TestFail('Must run for at least 10 seconds') with chrome.Chrome(): # Audio loop time should be significantly shorter than # |run_time_sec| time, so that the total playback time doesn't # exceed it by much. audio_loop_time_sec = min(10, run_time_sec / 10 + 0.5) # Set a low audio volume to avoid annoying people during tests. audio_helper.set_volume_levels(10, 100) # Start a subprocess that uses dbus-monitor to listen for suspend # announcements from powerd and writes the output to a log. dbus_log_fd, dbus_log_name = tempfile.mkstemp() os.unlink(dbus_log_name) dbus_log = os.fdopen(dbus_log_fd) dbus_proc = subprocess.Popen( 'dbus-monitor --monitor --system ' + '"type=\'signal\',interface=\'org.chromium.PowerManager\',' + 'member=\'SuspendImminent\'"', shell=True, stdout=dbus_log) # Start playing audio file. self._enable_audio_playback = True thread = threading.Thread(target=self._play_audio, args=(audio_loop_time_sec, )) thread.start() # Restart powerd with timeouts for quick idle events. gap_ms = run_time_sec * 1000 / 4 dim_ms = min(10000, gap_ms) off_ms = min(20000, gap_ms * 2) suspend_ms = min(30000, gap_ms * 3) prefs = { 'disable_idle_suspend': 0, 'ignore_external_policy': 1, 'plugged_dim_ms': dim_ms, 'plugged_off_ms': off_ms, 'plugged_suspend_ms': suspend_ms, 'unplugged_dim_ms': dim_ms, 'unplugged_off_ms': off_ms, 'unplugged_suspend_ms': suspend_ms } self._pref_change = power_utils.PowerPrefChanger(prefs) # Set an alarm to wake up the system in case the audio detector # fails and the system suspends. alarm_time = rtc.get_seconds() + run_time_sec rtc.set_wake_alarm(alarm_time) time.sleep(run_time_sec) # Stop powerd to avoid suspending when the audio stops. utils.system_output('stop powerd') # Stop audio and wait for the audio thread to terminate. self._enable_audio_playback = False thread.join(timeout=(audio_loop_time_sec * 2)) if thread.is_alive(): logging.error('Audio thread did not terminate at end of test.') # Check the D-Bus log to make sure that no suspend took place. # dbus-monitor logs messages about its initial connection to the bus # in addition to the signals that we asked it for, so look for the # signal name in its output. dbus_proc.kill() dbus_log.seek(0) if 'SuspendImminent' in dbus_log.read(): err_str = 'System suspended while audio was playing.' raise error.TestFail(err_str)
def run_once(self, test_hours=None, sample_hours=None, percent_initial_charge_min=0.2, max_milliwatts_standby=None): if test_hours <= sample_hours: raise error.TestFail( "Test hours must be greater than sample hours") # If we're measuring <= 6min of S3 then the S0 time is not negligible. # Note, reasonable rule of thumb is S0 idle is ~10-20 times S3 power. if sample_hours < self._min_sample_hours: raise error.TestFail("Must suspend more than %.2f hours" % \ sample_hours) # Query initial power status power_stats = power_status.get_status() power_stats.assert_battery_state(percent_initial_charge_min) charge_start = power_stats.battery[0].charge_now voltage_start = power_stats.battery[0].voltage_now max_hours = charge_start * voltage_start / \ (max_milliwatts_standby / 1000) if max_hours < test_hours: raise error.TestFail('Battery not charged adequately for test') elapsed_hours = 0 while elapsed_hours < test_hours: charge_before = power_stats.battery[0].charge_now before_suspend_secs = rtc.get_seconds() sys_power.do_suspend(sample_hours * 3600) after_suspend_secs = rtc.get_seconds() power_stats.refresh() if power_stats.percent_current_charge() < self._percent_min_charge: logging.warning( "Battery percent = %.2f%%. Too low to continue") break # check that the RTC slept the correct amount of time as there could # potentially be another wake source that would spoil the test. actual_hours = (after_suspend_secs - before_suspend_secs) / 3600.0 logging.debug("actual_hours = %.4f", actual_hours) percent_diff = math.fabs((actual_hours - sample_hours) / ((actual_hours + sample_hours) / 2) * 100) if percent_diff > 2: err_str = "Requested S3 time and actual varied by %.2f%%." \ % percent_diff raise error.TestFail(err_str) # Check resulting charge consumption charge_used = charge_before - power_stats.battery[0].charge_now logging.debug("charge_used = %.6f", charge_used) elapsed_hours += actual_hours logging.debug("elapsed_hours = %.4f", elapsed_hours) charge_end = power_stats.battery[0].charge_now voltage_end = power_stats.battery[0].voltage_now standby_hours = power_stats.battery[0].charge_full_design / \ (charge_start - charge_end) * elapsed_hours energy_used = charge_start * voltage_start - charge_end * voltage_end if energy_used <= 0: raise error.TestError("Energy used reading is suspect.") standby_milliwatts = energy_used / elapsed_hours * 1000 results = {} results['milliwatts_standby_power'] = standby_milliwatts results['hours_standby_time'] = standby_hours self.write_perf_keyval(results) # need to sleep for some time to allow network connection to return time.sleep(10)
def run_once(self, test_hours=None, sample_hours=None, max_milliwatts_standby=500, ac_ok=False, force_discharge=False, suspend_state='', bypass_check=False): """Put DUT to suspend state for |sample_hours| and measure power.""" if not power_utils.has_battery(): raise error.TestNAError( 'Skipping test because DUT has no battery.') if test_hours < sample_hours: raise error.TestFail('Test hours must be greater than sample ' 'hours.') # If we're measuring < 6min of standby then the S0 time is not # negligible. Note, reasonable rule of thumb is S0 idle is ~10-20 times # standby power. if sample_hours < self._min_sample_hours and not bypass_check: raise error.TestFail('Must standby more than %.2f hours.' % \ sample_hours) power_stats = power_status.get_status() if not ac_ok and power_stats.on_ac(): raise error.TestError('On AC, please unplug power supply.') if force_discharge: if not power_stats.on_ac(): raise error.TestError('Not on AC, please plug in power supply ' 'to attempt force discharge.') if not power_utils.charge_control_by_ectool(False): raise error.TestError('Unable to force discharge.') self._force_discharge_enabled = True charge_start = power_stats.battery[0].charge_now voltage_start = power_stats.battery[0].voltage_now max_hours = ((charge_start * voltage_start) / (max_milliwatts_standby / 1000.)) if max_hours < test_hours: raise error.TestFail('Battery not charged adequately for test.') suspender = power_suspend.Suspender(self.resultsdir, suspend_state=suspend_state) elapsed_hours = 0 results = {} loop = 0 start_ts = time.time() while elapsed_hours < test_hours: charge_before = power_stats.battery[0].charge_now before_suspend_secs = rtc.get_seconds() suspender.suspend(duration=sample_hours * 3600) after_suspend_secs = rtc.get_seconds() power_stats.refresh() if power_stats.percent_current_charge() < self._percent_min_charge: logging.warning('Battery = %.2f%%. Too low to continue.') break # check that the RTC slept the correct amount of time as there could # potentially be another wake source that would spoil the test. actual_hours = (after_suspend_secs - before_suspend_secs) / 3600.0 percent_diff = math.fabs((actual_hours - sample_hours) / ((actual_hours + sample_hours) / 2) * 100) if percent_diff > 2 and not bypass_check: err = 'Requested standby time and actual varied by %.2f%%.' \ % percent_diff raise error.TestFail(err) # Check resulting charge consumption charge_used = charge_before - power_stats.battery[0].charge_now elapsed_hours += actual_hours logging.debug( 'loop%d done: loop hours %.3f, elapsed hours %.3f ' 'charge used: %.3f', loop, actual_hours, elapsed_hours, charge_used) loop += 1 end_ts = time.time() offset = (end_ts - start_ts - elapsed_hours * 3600) / 2. offset += suspender.get_suspend_delay() start_ts += offset end_ts -= offset power_telemetry_utils.start_measurement(start_ts) power_telemetry_utils.end_measurement(end_ts) self._checkpoint_logger.checkpoint(self.tagged_testname, start_ts, end_ts) charge_end = power_stats.battery[0].charge_now total_charge_used = charge_start - charge_end if total_charge_used <= 0 and not bypass_check: raise error.TestError('Charge used is suspect.') voltage_end = power_stats.battery[0].voltage_now standby_hours = power_stats.battery[0].charge_full_design / \ total_charge_used * elapsed_hours energy_used = (voltage_start + voltage_end) / 2 * \ total_charge_used results['ah_charge_start'] = charge_start results['ah_charge_now'] = charge_end results['ah_charge_used'] = total_charge_used results['force_discharge'] = self._force_discharge_enabled results['hours_standby_time'] = standby_hours results['hours_standby_time_tested'] = elapsed_hours results['v_voltage_start'] = voltage_start results['v_voltage_now'] = voltage_end results['w_energy_rate'] = energy_used / elapsed_hours results['wh_energy_used'] = energy_used self.write_perf_keyval(results) pdash = power_dashboard.SimplePowerLoggerDashboard( end_ts - start_ts, results['w_energy_rate'], self.tagged_testname, start_ts, self.resultsdir, note=self._pdash_note) pdash.upload() self._checkpoint_logger.save_checkpoint_data(self.resultsdir) self.output_perf_value(description='hours_standby_time', value=results['hours_standby_time'], units='hours', higher_is_better=True) self.output_perf_value(description='w_energy_rate', value=results['w_energy_rate'], units='watts', higher_is_better=False) # need to sleep for some time to allow network connection to return time.sleep(10)
def suspend_to_ram(secs_to_suspend=5): logging.info('Scheduling wakeup in %d seconds\n', secs_to_suspend) sys_power.do_suspend(secs_to_suspend) logging.info('Woke up at %d', rtc.get_seconds())