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())