| # Lint as: python2, python3 | |
| # 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 collections | |
| import json | |
| import logging | |
| import numpy | |
| import os | |
| import re | |
| import time | |
| from autotest_lib.client.bin import utils | |
| from autotest_lib.client.common_lib import error | |
| from autotest_lib.client.common_lib import utils as _utils | |
| from autotest_lib.client.common_lib.cros import arc | |
| from autotest_lib.client.common_lib.cros import arc_common | |
| from autotest_lib.client.common_lib.cros import chrome | |
| from autotest_lib.client.common_lib.cros import power_load_util | |
| from autotest_lib.client.common_lib.cros.network import interface | |
| from autotest_lib.client.common_lib.cros.network import xmlrpc_datatypes | |
| from autotest_lib.client.common_lib.cros.network import xmlrpc_security_types | |
| from autotest_lib.client.cros import backchannel | |
| from autotest_lib.client.cros import httpd | |
| from autotest_lib.client.cros import memory_bandwidth_logger | |
| from autotest_lib.client.cros import service_stopper | |
| from autotest_lib.client.cros.audio import audio_helper | |
| from autotest_lib.client.cros.networking import cellular_proxy | |
| from autotest_lib.client.cros.networking import shill_proxy | |
| from autotest_lib.client.cros.networking import wifi_proxy | |
| from autotest_lib.client.cros.power import power_dashboard | |
| from autotest_lib.client.cros.power import power_status | |
| from autotest_lib.client.cros.power import power_utils | |
| from autotest_lib.client.cros.power import force_discharge_utils | |
| from telemetry.core import exceptions | |
| params_dict = { | |
| 'test_time_ms': '_mseconds', | |
| 'should_scroll': '_should_scroll', | |
| 'should_scroll_up': '_should_scroll_up', | |
| 'scroll_loop': '_scroll_loop', | |
| 'scroll_interval_ms': '_scroll_interval_ms', | |
| 'scroll_by_pixels': '_scroll_by_pixels', | |
| 'tasks': '_tasks', | |
| } | |
| class power_LoadTest(arc.ArcTest): | |
| """test class""" | |
| version = 2 | |
| def initialize(self, | |
| percent_initial_charge_min=None, | |
| check_network=True, | |
| loop_time=3600, | |
| loop_count=1, | |
| should_scroll='true', | |
| should_scroll_up='true', | |
| scroll_loop='false', | |
| scroll_interval_ms='10000', | |
| scroll_by_pixels='600', | |
| test_low_batt_p=3, | |
| verbose=True, | |
| force_wifi=False, | |
| wifi_ap='', | |
| wifi_sec='none', | |
| wifi_pw='', | |
| wifi_timeout=60, | |
| use_cellular_network=False, | |
| tasks='', | |
| volume_level=10, | |
| mic_gain=10, | |
| low_batt_margin_p=2, | |
| ac_ok=False, | |
| log_mem_bandwidth=False, | |
| gaia_login=None, | |
| force_discharge='false', | |
| pdash_note=''): | |
| """ | |
| percent_initial_charge_min: min battery charge at start of test | |
| check_network: check that Ethernet interface is not running | |
| loop_time: length of time to run the test for in each loop | |
| loop_count: number of times to loop the test for | |
| should_scroll: should the extension scroll pages | |
| should_scroll_up: should scroll in up direction | |
| scroll_loop: continue scrolling indefinitely | |
| scroll_interval_ms: how often to scoll | |
| scroll_by_pixels: number of pixels to scroll each time | |
| test_low_batt_p: percent battery at which test should stop | |
| verbose: add more logging information | |
| force_wifi: should we force to test to run on wifi | |
| wifi_ap: the name (ssid) of the wifi access point | |
| wifi_sec: the type of security for the wifi ap | |
| wifi_pw: password for the wifi ap | |
| wifi_timeout: The timeout for wifi configuration | |
| use_cellular_network: use the cellular network connection instead of wifi | |
| volume_level: percent audio volume level | |
| mic_gain: percent audio microphone gain level | |
| low_batt_margin_p: percent low battery margin to be added to | |
| sys_low_batt_p to guarantee test completes prior to powerd shutdown | |
| ac_ok: boolean to allow running on AC | |
| log_mem_bandwidth: boolean to log memory bandwidth during the test | |
| gaia_login: whether real GAIA login should be attempted. If 'None' | |
| (default) then boolean is determined from URL. | |
| force_discharge: string of whether to tell ec to discharge battery even | |
| when the charger is plugged in. 'false' means no forcing discharge; | |
| 'true' means forcing discharge and raising an error when it fails; | |
| 'optional' means forcing discharge when possible but not raising an | |
| error when it fails, which is more friendly to devices without a | |
| battery. | |
| pdash_note: note of the current run to send to power dashboard. | |
| """ | |
| self._backlight = None | |
| self._services = None | |
| self._browser = None | |
| self._loop_time = loop_time | |
| self._loop_count = loop_count | |
| self._mseconds = self._loop_time * 1000 | |
| self._verbose = verbose | |
| self._sys_low_batt_p = 0. | |
| self._sys_low_batt_s = 0. | |
| self._test_low_batt_p = test_low_batt_p | |
| self._should_scroll = should_scroll | |
| self._should_scroll_up = should_scroll_up | |
| self._scroll_loop = scroll_loop | |
| self._scroll_interval_ms = scroll_interval_ms | |
| self._scroll_by_pixels = scroll_by_pixels | |
| self._tmp_keyvals = {} | |
| self._power_status = None | |
| self._force_wifi = force_wifi | |
| self._use_cellular_network = use_cellular_network | |
| self._testServer = None | |
| self._tasks = tasks | |
| self._backchannel = None | |
| self._shill_proxy = None | |
| self._volume_level = volume_level | |
| self._mic_gain = mic_gain | |
| self._ac_ok = ac_ok | |
| self._log_mem_bandwidth = log_mem_bandwidth | |
| self._wait_time = 60 | |
| self._stats = collections.defaultdict(list) | |
| self._pdash_note = pdash_note | |
| self._power_status = power_status.get_status() | |
| self._force_discharge_success = force_discharge_utils.process( | |
| force_discharge, self._power_status) | |
| if self._force_discharge_success: | |
| self._ac_ok = True | |
| if not self._power_status.battery: | |
| if ac_ok and (power_utils.has_powercap_support() or | |
| power_utils.has_rapl_support()): | |
| logging.info("Device has no battery but has powercap data.") | |
| else: | |
| rsp = "Skipping test for device without battery and powercap." | |
| raise error.TestNAError(rsp) | |
| self._tmp_keyvals['b_on_ac'] = int(not self._force_discharge_success | |
| and self._power_status.on_ac()) | |
| self._tmp_keyvals['force_discharge'] = int( | |
| self._force_discharge_success) | |
| self._gaia_login = gaia_login | |
| if gaia_login is None: | |
| self._gaia_login = power_load_util.use_gaia_login() | |
| self._username = power_load_util.get_username() | |
| self._password = power_load_util.get_password() | |
| if not self._ac_ok: | |
| self._power_status.assert_battery_state(percent_initial_charge_min) | |
| # If force wifi enabled, convert eth0 to backchannel and connect to the | |
| # specified WiFi AP. | |
| if self._force_wifi: | |
| if self._use_cellular_network: | |
| raise error.TestError("Can't force WiFi AP when cellular network" | |
| "is used"); | |
| sec_config = None | |
| # TODO(dbasehore): Fix this when we get a better way of figuring out | |
| # the wifi security configuration. | |
| if wifi_sec == 'rsn' or wifi_sec == 'wpa': | |
| sec_config = xmlrpc_security_types.WPAConfig( | |
| psk=wifi_pw, | |
| wpa_mode=xmlrpc_security_types.WPAConfig.MODE_PURE_WPA2, | |
| wpa2_ciphers= | |
| [xmlrpc_security_types.WPAConfig.CIPHER_CCMP]) | |
| wifi_config = xmlrpc_datatypes.AssociationParameters( | |
| ssid=wifi_ap, security_config=sec_config, | |
| configuration_timeout=wifi_timeout) | |
| # If backchannel is already running, don't run it again. | |
| self._backchannel = backchannel.Backchannel() | |
| if not self._backchannel.setup(): | |
| raise error.TestError('Could not setup Backchannel network.') | |
| self._shill_proxy = wifi_proxy.WifiProxy() | |
| self._shill_proxy.remove_all_wifi_entries() | |
| for i in range(1, 4): | |
| raw_output = self._shill_proxy.connect_to_wifi_network( | |
| wifi_config.ssid, | |
| wifi_config.security, | |
| wifi_config.security_parameters, | |
| wifi_config.save_credentials, | |
| station_type=wifi_config.station_type, | |
| hidden_network=wifi_config.is_hidden, | |
| discovery_timeout_seconds= | |
| wifi_config.discovery_timeout, | |
| association_timeout_seconds= | |
| wifi_config.association_timeout, | |
| configuration_timeout_seconds= | |
| wifi_config.configuration_timeout * i) | |
| result = xmlrpc_datatypes.AssociationResult. \ | |
| from_dbus_proxy_output(raw_output) | |
| if result.success: | |
| break | |
| logging.warning('wifi connect: disc:%d assoc:%d config:%d fail:%s', | |
| result.discovery_time, result.association_time, | |
| result.configuration_time, result.failure_reason) | |
| else: | |
| raise error.TestError('Could not connect to WiFi network.') | |
| else: | |
| # Find all wired ethernet interfaces. | |
| ifaces = [ iface for iface in interface.get_interfaces() | |
| if (not iface.is_wifi_device() and | |
| iface.name.startswith('eth')) ] | |
| logging.debug(str([iface.name for iface in ifaces])) | |
| for iface in ifaces: | |
| if check_network and iface.is_lower_up: | |
| raise error.TestError('Ethernet interface is active. ' + | |
| 'Please remove Ethernet cable') | |
| if self._use_cellular_network: | |
| self._shill_proxy = cellular_proxy.CellularProxy() | |
| cdev = self._shill_proxy.find_cellular_device_object() | |
| if cdev is None: | |
| raise error.TestError("No cellular device found") | |
| self._shill_proxy.manager.DisableTechnology( | |
| shill_proxy.ShillProxy.TECHNOLOGY_WIFI) | |
| self._shill_proxy.wait_for_cellular_service_object() | |
| # record the max backlight level | |
| self._backlight = power_utils.Backlight( | |
| force_battery=self._force_discharge_success) | |
| self._tmp_keyvals['level_backlight_max'] = \ | |
| self._backlight.get_max_level() | |
| self._services = service_stopper.ServiceStopper( | |
| service_stopper.ServiceStopper.POWER_DRAW_SERVICES) | |
| self._detachable_handler = power_utils.BaseActivitySimulator() | |
| # fix up file perms for the power test extension so that chrome | |
| # can access it | |
| os.system('chmod -R 755 %s' % self.bindir) | |
| # setup a HTTP Server to listen for status updates from the power | |
| # test extension | |
| self._testServer = httpd.HTTPListener(8001, docroot=self.bindir) | |
| self._testServer.run() | |
| # initialize various interesting power related stats | |
| self._statomatic = power_status.StatoMatic() | |
| self._power_status.refresh() | |
| self._sys_low_batt_p = float(utils.system_output( | |
| 'check_powerd_config --low_battery_shutdown_percent')) | |
| self._sys_low_batt_s = int(utils.system_output( | |
| 'check_powerd_config --low_battery_shutdown_time')) | |
| if self._sys_low_batt_p and self._sys_low_batt_s: | |
| raise error.TestError( | |
| "Low battery percent and seconds are non-zero.") | |
| min_low_batt_p = min(self._sys_low_batt_p + low_batt_margin_p, 100) | |
| if self._sys_low_batt_p and (min_low_batt_p > self._test_low_batt_p): | |
| logging.warning("test low battery threshold is below system " + | |
| "low battery requirement. Setting to %f", | |
| min_low_batt_p) | |
| self._test_low_batt_p = min_low_batt_p | |
| if self._power_status.battery: | |
| self._ah_charge_start = self._power_status.battery.charge_now | |
| self._wh_energy_start = self._power_status.battery.energy | |
| self.task_monitor_file = open(os.path.join(self.resultsdir, | |
| 'task-monitor.json'), | |
| mode='wt', | |
| **power_utils.encoding_kwargs()) | |
| def run_once(self): | |
| """Test main loop.""" | |
| t0 = time.time() | |
| # record the PSR related info. | |
| psr = power_utils.DisplayPanelSelfRefresh(init_time=t0) | |
| try: | |
| self._keyboard_backlight = power_utils.KbdBacklight() | |
| self._set_keyboard_backlight_level() | |
| except power_utils.KbdBacklightException as e: | |
| logging.info("Assuming no keyboard backlight due to :: %s", str(e)) | |
| self._keyboard_backlight = None | |
| self._checkpoint_logger = power_status.CheckpointLogger() | |
| seconds_period = 20.0 | |
| self._meas_logs = power_status.create_measurement_loggers( | |
| seconds_period, self._checkpoint_logger) | |
| for log in self._meas_logs: | |
| log.start() | |
| if self._log_mem_bandwidth: | |
| self._mlog = memory_bandwidth_logger.MemoryBandwidthLogger( | |
| raw=False, seconds_period=2) | |
| self._mlog.start() | |
| # record start time and end time for each task | |
| self._task_tracker = [] | |
| ext_path = os.path.join(os.path.dirname(__file__), 'extension') | |
| self._tmp_keyvals['username'] = self._username | |
| arc_mode = arc_common.ARC_MODE_DISABLED | |
| if utils.is_arc_available(): | |
| arc_mode = arc_common.ARC_MODE_ENABLED | |
| # --disable-sync disables test account info sync, eg. Wi-Fi credentials, | |
| # so that each test run does not remember info from last test run. | |
| extra_browser_args = ['--disable-sync'] | |
| # b/228256145 to avoid powerd restart | |
| extra_browser_args.append('--disable-features=FirmwareUpdaterApp') | |
| try: | |
| self._browser = chrome.Chrome( | |
| extension_paths=[ext_path], | |
| extra_browser_args=extra_browser_args, | |
| gaia_login=self._gaia_login, | |
| username=self._username, | |
| password=self._password, | |
| arc_mode=arc_mode) | |
| except exceptions.LoginException: | |
| # already failed guest login | |
| if not self._gaia_login: | |
| raise | |
| self._gaia_login = False | |
| logging.warning("Unable to use GAIA acct %s. Using GUEST instead.\n", | |
| self._username) | |
| self._browser = chrome.Chrome(extension_paths=[ext_path], | |
| gaia_login=self._gaia_login) | |
| if not self._gaia_login: | |
| self._tmp_keyvals['username'] = 'GUEST' | |
| self._tmp_keyvals['gaia_login'] = int(self._gaia_login) | |
| extension = self._browser.get_extension(ext_path) | |
| for k in params_dict: | |
| if getattr(self, params_dict[k]) is not '': | |
| extension.ExecuteJavaScript('var %s = %s;' % | |
| (k, getattr(self, params_dict[k]))) | |
| # Stop the services after the browser is setup. This ensures that | |
| # restart ui does not restart services e.g. powerd underneath us | |
| self._services.stop_services() | |
| # This opens a trap start page to capture tabs opened for first login. | |
| # It will be closed when startTest is run. | |
| extension.ExecuteJavaScript('chrome.windows.create(null, null);') | |
| for i in range(self._loop_count): | |
| start_time = time.time() | |
| extension.ExecuteJavaScript('startTest();') | |
| # the power test extension will report its status here | |
| latch = self._testServer.add_wait_url('/status') | |
| # this starts a thread in the server that listens to log | |
| # information from the script | |
| script_logging = self._testServer.add_wait_url(url='/log') | |
| # dump any log entry that comes from the script into | |
| # the debug log | |
| self._testServer.add_url_handler(url='/log',\ | |
| handler_func=(lambda handler, forms, loop_counter=i:\ | |
| _extension_log_handler(handler, forms, loop_counter))) | |
| pagetime_tracking = self._testServer.add_wait_url(url='/pagetime') | |
| self._testServer.add_url_handler(url='/pagetime',\ | |
| handler_func=(lambda handler, forms, test_instance=self, | |
| loop_counter=i:\ | |
| _extension_page_time_info_handler(handler, forms, | |
| loop_counter, | |
| test_instance))) | |
| keyvalues_tracking = self._testServer.add_wait_url(url='/keyvalues') | |
| self._testServer.add_url_handler(url='/keyvalues',\ | |
| handler_func=(lambda handler, forms, test_instance=self, | |
| loop_counter=i:\ | |
| _extension_key_values_handler(handler, forms, | |
| loop_counter, | |
| test_instance))) | |
| self._testServer.add_url(url='/task-monitor') | |
| self._testServer.add_url_handler( | |
| url='/task-monitor', | |
| handler_func=lambda handler, forms: | |
| self._extension_task_monitor_handler(handler, forms) | |
| ) | |
| # setup a handler to simulate waking up the base of a detachable | |
| # on user interaction. On scrolling, wake for 1s, on page | |
| # navigation, wake for 10s. | |
| self._testServer.add_url(url='/pagenav') | |
| self._testServer.add_url(url='/scroll') | |
| self._testServer.add_url_handler(url='/pagenav', | |
| handler_func=(lambda handler, args, plt=self: | |
| plt._detachable_handler.wake_base(10000))) | |
| self._testServer.add_url_handler(url='/scroll', | |
| handler_func=(lambda handler, args, plt=self: | |
| plt._detachable_handler.wake_base(1000))) | |
| # reset backlight level since powerd might've modified it | |
| # based on ambient light | |
| self._set_backlight_level(i) | |
| self._set_lightbar_level() | |
| if self._keyboard_backlight: | |
| self._set_keyboard_backlight_level(loop=i) | |
| audio_helper.set_volume_levels(self._volume_level, | |
| self._mic_gain) | |
| low_battery = self._do_wait(self._verbose, self._loop_time, | |
| latch) | |
| script_logging.set() | |
| pagetime_tracking.set() | |
| keyvalues_tracking.set() | |
| self._log_loop_checkpoint(i, start_time, time.time()) | |
| if self._verbose: | |
| logging.debug('loop %d completed', i) | |
| if low_battery: | |
| logging.info('Exiting due to low battery') | |
| break | |
| # done with logging from the script, so we can collect that thread | |
| t1 = time.time() | |
| psr.refresh() | |
| self._tmp_keyvals['minutes_battery_life_tested'] = (t1 - t0) / 60 | |
| self._tmp_keyvals.update(psr.get_keyvals()) | |
| self._start_time = t0 | |
| self._end_time = t1 | |
| def postprocess_iteration(self): | |
| """Postprocess: write keyvals / log and send data to power dashboard.""" | |
| def _log_stats(prefix, stats): | |
| if not len(stats): | |
| return | |
| np = numpy.array(stats) | |
| logging.debug("%s samples: %d", prefix, len(np)) | |
| logging.debug("%s mean: %.2f", prefix, np.mean()) | |
| logging.debug("%s stdev: %.2f", prefix, np.std()) | |
| logging.debug("%s max: %.2f", prefix, np.max()) | |
| logging.debug("%s min: %.2f", prefix, np.min()) | |
| def _log_per_loop_stats(): | |
| samples_per_loop = int(self._loop_time / self._wait_time) + 1 | |
| for kname in self._stats: | |
| start_idx = 0 | |
| loop = 1 | |
| for end_idx in range(samples_per_loop, len(self._stats[kname]), | |
| samples_per_loop): | |
| _log_stats("%s loop %d" % (kname, loop), | |
| self._stats[kname][start_idx:end_idx]) | |
| loop += 1 | |
| start_idx = end_idx | |
| def _log_all_stats(): | |
| for kname in self._stats: | |
| _log_stats(kname, self._stats[kname]) | |
| for task, tstart, tend in self._task_tracker: | |
| self._checkpoint_logger.checkpoint('_' + task, tstart, tend) | |
| keyvals = {} | |
| for log in self._meas_logs: | |
| keyvals.update(log.calc()) | |
| keyvals.update(self._statomatic.publish()) | |
| if self._log_mem_bandwidth: | |
| self._mlog.stop() | |
| self._mlog.join() | |
| _log_all_stats() | |
| _log_per_loop_stats() | |
| # record battery stats | |
| if self._power_status.battery: | |
| keyvals['a_current_now'] = self._power_status.battery.current_now | |
| keyvals['ah_charge_full'] = \ | |
| self._power_status.battery.charge_full | |
| keyvals['ah_charge_full_design'] = \ | |
| self._power_status.battery.charge_full_design | |
| keyvals['ah_charge_start'] = self._ah_charge_start | |
| keyvals['ah_charge_now'] = self._power_status.battery.charge_now | |
| keyvals['ah_charge_used'] = keyvals['ah_charge_start'] - \ | |
| keyvals['ah_charge_now'] | |
| keyvals['wh_energy_start'] = self._wh_energy_start | |
| keyvals['wh_energy_now'] = self._power_status.battery.energy | |
| keyvals['wh_energy_used'] = keyvals['wh_energy_start'] - \ | |
| keyvals['wh_energy_now'] | |
| keyvals['v_voltage_min_design'] = \ | |
| self._power_status.battery.voltage_min_design | |
| keyvals['wh_energy_full_design'] = \ | |
| self._power_status.battery.energy_full_design | |
| keyvals['v_voltage_now'] = self._power_status.battery.voltage_now | |
| keyvals.update(self._tmp_keyvals) | |
| keyvals['percent_sys_low_battery'] = self._sys_low_batt_p | |
| keyvals['seconds_sys_low_battery'] = self._sys_low_batt_s | |
| voltage_np = numpy.array(self._stats['v_voltage_now']) | |
| voltage_mean = voltage_np.mean() | |
| keyvals['v_voltage_mean'] = voltage_mean | |
| keyvals['wh_energy_powerlogger'] = \ | |
| self._energy_use_from_powerlogger(keyvals) | |
| if (self._force_discharge_success or not self._power_status.on_ac() | |
| ) and keyvals['ah_charge_used'] > 0: | |
| # For full runs, we should use charge to scale for battery life, | |
| # since the voltage swing is accounted for. | |
| # For short runs, energy will be a better estimate. | |
| # TODO(b/188082306): some devices do not provide | |
| # 'wh_energy_powerlogger' so use charge in this case to scale for | |
| # battery life. | |
| if self._loop_count > 1 or keyvals['wh_energy_powerlogger'] <= 0: | |
| estimated_reps = (keyvals['ah_charge_full_design'] / | |
| keyvals['ah_charge_used']) | |
| else: | |
| estimated_reps = (keyvals['wh_energy_full_design'] / | |
| keyvals['wh_energy_powerlogger']) | |
| bat_life_scale = estimated_reps * \ | |
| ((100 - keyvals['percent_sys_low_battery']) / 100) | |
| keyvals['minutes_battery_life'] = bat_life_scale * \ | |
| keyvals['minutes_battery_life_tested'] | |
| # In the case where sys_low_batt_s is non-zero subtract those | |
| # minutes from the final extrapolation. | |
| if self._sys_low_batt_s: | |
| keyvals['minutes_battery_life'] -= self._sys_low_batt_s / 60 | |
| keyvals['a_current_rate'] = keyvals['ah_charge_used'] * 60 / \ | |
| keyvals['minutes_battery_life_tested'] | |
| keyvals['w_energy_rate'] = keyvals['wh_energy_used'] * 60 / \ | |
| keyvals['minutes_battery_life_tested'] | |
| if self._gaia_login: | |
| self.output_perf_value(description='minutes_battery_life', | |
| value=keyvals['minutes_battery_life'], | |
| units='minutes', | |
| higher_is_better=True) | |
| minutes_battery_life_tested = keyvals['minutes_battery_life_tested'] | |
| # TODO(coconutruben): overwrite write_perf_keyvals for all power | |
| # tests and replace this once power_LoadTest inherits from power_Test. | |
| # Dump all keyvals into debug keyvals. | |
| _utils.write_keyval(os.path.join(self.resultsdir, 'debug_keyval'), | |
| keyvals) | |
| # Avoid polluting the keyvals with non-core domains. | |
| core_keyvals = power_utils.get_core_keyvals(keyvals) | |
| for key, value in core_keyvals.items(): | |
| if re.match(r'percent_[cg]pu(idle|pkg).*_R?C0(_C1)?_time', key): | |
| self.output_perf_value(description=key, | |
| value=value, | |
| units='percent', | |
| higher_is_better=False) | |
| logger = power_dashboard.KeyvalLogger(self._start_time, self._end_time) | |
| for key in [ | |
| 'b_on_ac', 'force_discharge', 'gaia_login', | |
| 'percent_usb_suspended_time' | |
| ]: | |
| logger.add_item(key, keyvals[key], 'point', 'perf') | |
| # Add audio/docs/email/web fail load details to power dashboard and to keyval | |
| for task in ('audio', 'docs', 'email', 'web'): | |
| key = 'ext_%s_failed_loads' % task | |
| if key not in keyvals: | |
| continue | |
| vals = (int(x) for x in keyvals[key].split('_')) | |
| for index, val in enumerate(vals): | |
| log_name = 'loop%02d_%s_failed_load' % (index, task) | |
| logger.add_item(log_name, val, 'point', 'perf') | |
| core_keyvals[log_name] = val | |
| # Add ext_ms_page_load_time_mean to power dashboard | |
| if 'ext_ms_page_load_time_mean' in keyvals: | |
| vals = (float(x) | |
| for x in keyvals['ext_ms_page_load_time_mean'].split('_')) | |
| for index, val in enumerate(vals): | |
| log_name = 'loop%02d_ms_page_load_time' % index | |
| logger.add_item(log_name, val, 'point', 'perf') | |
| # Add battery life and power to power dashboard | |
| for key in ('minutes_battery_life_tested', 'minutes_battery_life', | |
| 'w_energy_rate'): | |
| if key in keyvals: | |
| logger.add_item(key, keyvals[key], 'point', 'perf') | |
| self._meas_logs.append(logger) | |
| self.write_perf_keyval(core_keyvals) | |
| for log in self._meas_logs: | |
| log.save_results(self.resultsdir) | |
| self._checkpoint_logger.save_checkpoint_data(self.resultsdir) | |
| if minutes_battery_life_tested * 60 < self._loop_time : | |
| logging.info('Data is less than 1 loop, skip sending to dashboard.') | |
| return | |
| dashboard_factory = power_dashboard.get_dashboard_factory() | |
| for log in self._meas_logs: | |
| dashboard = dashboard_factory.createDashboard(log, | |
| self.tagged_testname, self.resultsdir, note=self._pdash_note) | |
| dashboard.upload() | |
| power_dashboard.generate_parallax_report(self.outputdir) | |
| def cleanup(self): | |
| force_discharge_utils.restore(self._force_discharge_success) | |
| if self._backlight: | |
| self._backlight.restore() | |
| if self._services: | |
| self._services.restore_services() | |
| audio_helper.set_default_volume_levels() | |
| self._detachable_handler.restore() | |
| if self.task_monitor_file: | |
| self.task_monitor_file.close() | |
| self._generate_task_monitor_html() | |
| if self._shill_proxy: | |
| if self._force_wifi: | |
| # cleanup backchannel interface | |
| # Prevent wifi congestion in test lab by forcing machines to forget the | |
| # wifi AP we connected to at the start of the test. | |
| self._shill_proxy.remove_all_wifi_entries() | |
| if self._use_cellular_network: | |
| self._shill_proxy.manager.EnableTechnology( | |
| shill_proxy.ShillProxy.TECHNOLOGY_WIFI) | |
| if self._backchannel: | |
| self._backchannel.teardown() | |
| if self._browser: | |
| self._browser.close() | |
| if self._testServer: | |
| self._testServer.stop() | |
| def _do_wait(self, verbose, seconds, latch): | |
| latched = False | |
| low_battery = False | |
| total_time = seconds + self._wait_time | |
| elapsed_time = 0 | |
| while elapsed_time < total_time: | |
| time.sleep(self._wait_time) | |
| elapsed_time += self._wait_time | |
| self._power_status.refresh() | |
| if not self._ac_ok and self._power_status.on_ac(): | |
| raise error.TestError('Running on AC power now.') | |
| if self._power_status.battery: | |
| if (not self._ac_ok and | |
| self._power_status.battery.status != 'Discharging'): | |
| raise error.TestFail('The battery is not discharging.') | |
| charge_now = self._power_status.battery.charge_now | |
| energy_rate = self._power_status.battery.energy_rate | |
| voltage_now = self._power_status.battery.voltage_now | |
| self._stats['w_energy_rate'].append(energy_rate) | |
| self._stats['v_voltage_now'].append(voltage_now) | |
| if verbose: | |
| logging.debug('ah_charge_now %f', charge_now) | |
| logging.debug('w_energy_rate %f', energy_rate) | |
| logging.debug('v_voltage_now %f', voltage_now) | |
| low_battery = (self._power_status.percent_current_charge() < | |
| self._test_low_batt_p) | |
| latched = latch.is_set() | |
| if latched or low_battery: | |
| break | |
| if latched: | |
| # record chrome power extension stats | |
| form_data = self._testServer.get_form_entries() | |
| logging.debug(form_data) | |
| for e in form_data: | |
| key = 'ext_' + e | |
| if key in self._tmp_keyvals: | |
| self._tmp_keyvals[key] += "_%s" % form_data[e] | |
| else: | |
| self._tmp_keyvals[key] = form_data[e] | |
| else: | |
| logging.debug("Didn't get status back from power extension") | |
| return low_battery | |
| def _set_backlight_level(self, loop=None): | |
| self._backlight.set_default() | |
| # record brightness level | |
| self._tmp_keyvals[_loop_keyname(loop, 'level_backlight')] = \ | |
| self._backlight.get_level() | |
| def _set_lightbar_level(self, level='off'): | |
| """Set lightbar level. | |
| Args: | |
| level: string value to set lightbar to. See ectool for more details. | |
| """ | |
| rv = utils.system('which ectool', ignore_status=True) | |
| if rv: | |
| return | |
| rv = utils.system('ectool lightbar %s' % level, ignore_status=True) | |
| if rv: | |
| logging.info('Assuming no lightbar due to non-zero exit status') | |
| else: | |
| logging.info('Setting lightbar to %s', level) | |
| self._tmp_keyvals['level_lightbar_current'] = level | |
| def _has_light_sensor(self): | |
| """ | |
| Determine if there is a light sensor on the board. | |
| @returns True if this host has a light sensor or | |
| False if it does not. | |
| """ | |
| # If the command exits with a failure status, | |
| # we do not have a light sensor | |
| cmd = 'check_powerd_config --ambient_light_sensor' | |
| result = utils.run(cmd, ignore_status=True) | |
| if result.exit_status: | |
| logging.debug('Ambient light sensor not present') | |
| return False | |
| logging.debug('Ambient light sensor present') | |
| return True | |
| def _energy_use_from_powerlogger(self, keyval): | |
| """ | |
| Calculates the energy use, in Wh, used over the course of the run as | |
| reported by the PowerLogger. | |
| Args: | |
| keyval: the dictionary of keyvals containing PowerLogger output | |
| Returns: | |
| energy_wh: total energy used over the course of this run | |
| """ | |
| energy_wh = 0 | |
| loop = 0 | |
| while True: | |
| duration_key = _loop_keyname(loop, 'system_duration') | |
| avg_power_key = _loop_keyname(loop, 'system_pwr_avg') | |
| if duration_key not in keyval or avg_power_key not in keyval: | |
| break | |
| energy_wh += keyval[duration_key] * keyval[avg_power_key] / 3600 | |
| loop += 1 | |
| return energy_wh | |
| def _has_hover_detection(self): | |
| """ | |
| Checks if hover is detected by the device. | |
| Returns: | |
| Returns True if the hover detection support is enabled. | |
| Else returns false. | |
| """ | |
| cmd = 'check_powerd_config --hover_detection' | |
| result = utils.run(cmd, ignore_status=True) | |
| if result.exit_status: | |
| logging.debug('Hover not present') | |
| return False | |
| logging.debug('Hover present') | |
| return True | |
| def _set_keyboard_backlight_level(self, loop=None): | |
| """ | |
| Sets keyboard backlight based on light sensor and hover. | |
| These values are based on UMA as mentioned in | |
| https://bugs.chromium.org/p/chromium/issues/detail?id=603233#c10 | |
| ALS | hover | keyboard backlight level | |
| --------------------------------------- | |
| No | No | default | |
| --------------------------------------- | |
| Yes | No | 40% of default | |
| -------------------------------------- | |
| No | Yes | System with this configuration does not exist | |
| -------------------------------------- | |
| Yes | Yes | 30% of default | |
| -------------------------------------- | |
| Here default is no Ambient Light Sensor, no hover, | |
| default always-on brightness level. | |
| """ | |
| default_level = self._keyboard_backlight.get_default_level() | |
| level_to_set = default_level | |
| has_light_sensor = self._has_light_sensor() | |
| has_hover = self._has_hover_detection() | |
| # TODO(ravisadineni):if (crbug: 603233) becomes default | |
| # change this to reflect it. | |
| if has_light_sensor and has_hover: | |
| level_to_set = (30 * default_level) / 100 | |
| elif has_light_sensor: | |
| level_to_set = (40 * default_level) / 100 | |
| elif has_hover: | |
| logging.warning('Device has hover but no light sensor') | |
| logging.info('Setting keyboard backlight to %d', level_to_set) | |
| self._keyboard_backlight.set_level(level_to_set) | |
| keyname = _loop_keyname(loop, 'percent_kbd_backlight') | |
| self._tmp_keyvals[keyname] = self._keyboard_backlight.get_percent() | |
| def _log_loop_checkpoint(self, loop, start, end): | |
| loop_str = _loop_prefix(loop) | |
| self._checkpoint_logger.checkpoint(loop_str, start, end) | |
| # Don't log section if we run custom tasks. | |
| if self._tasks != '': | |
| return | |
| sections = [ | |
| ('browsing', (0, 0.6)), | |
| ('email', (0.6, 0.8)), | |
| ('document', (0.8, 0.9)), | |
| ('video', (0.9, 1)), | |
| ] | |
| # Use start time from extension if found by look for google.com start. | |
| goog_str = loop_str + '_web_page_www.google.com' | |
| for item, start_extension, _ in self._task_tracker: | |
| if item == goog_str: | |
| if start_extension >= start: | |
| start = start_extension | |
| break | |
| logging.warning('Timestamp from extension (%.2f) is earlier than' | |
| 'timestamp from autotest (%.2f).', | |
| start_extension, start) | |
| # Use default loop duration for incomplete loop. | |
| duration = max(end - start, self._loop_time) | |
| for section, fractions in sections: | |
| s_start, s_end = (start + duration * fraction | |
| for fraction in fractions) | |
| if s_start > end: | |
| break | |
| if s_end > end: | |
| s_end = end | |
| self._checkpoint_logger.checkpoint(section, s_start, s_end) | |
| loop_section = '_' + loop_str + '_' + section | |
| self._checkpoint_logger.checkpoint(loop_section, s_start, s_end) | |
| def _extension_task_monitor_handler(self, handler, form): | |
| """ | |
| We use the httpd library to allow us to log chrome processes usage. | |
| """ | |
| if form: | |
| logging.debug("[task-monitor] got %d samples", len(form)) | |
| for idx in sorted(form.keys()): | |
| json = form[idx].value | |
| self.task_monitor_file.write(json) | |
| self.task_monitor_file.write(",\n") | |
| # we don't want to add url information to our keyvals. | |
| # httpd adds them automatically so we remove them again | |
| if idx in handler.server._form_entries: | |
| del handler.server._form_entries[idx] | |
| handler.send_response(200) | |
| def _generate_task_monitor_html(self): | |
| json_decoder = json.JSONDecoder() | |
| # regex pattern to simplify the url | |
| pattern = re.compile(r'.*https?://(www[.])?(?P<site>[^.]*[.][^/]*)') | |
| data = [] | |
| min_ts = None | |
| process_dict = {} | |
| process_id = 1 | |
| with open(os.path.join(self.resultsdir, 'task-monitor.json'), 'r', | |
| **power_utils.encoding_kwargs()) as f: | |
| json_strs = f.read().splitlines() | |
| for json_str in json_strs[1:]: | |
| if len(json_str) < 10: | |
| continue | |
| entry_dict, _ = json_decoder.raw_decode(json_str, 0) | |
| if not min_ts: | |
| min_ts = entry_dict['timestamp'] | |
| ts = (entry_dict['timestamp'] - min_ts) / 1000 | |
| items = {} | |
| for p in entry_dict['processes']: | |
| if 'cpu' not in p: | |
| continue | |
| tab = p['tasks'][0] | |
| key = tab['title'] | |
| if 'tabId' in tab: | |
| tabInfo = [ | |
| t for t in entry_dict['tabInfo'] | |
| if t['tabId'] == tab['tabId'] | |
| ] | |
| if len(tabInfo) > 0 and 'url' in tabInfo[0]: | |
| url = tabInfo[0]['url'] | |
| key = 'Tab: ' + pattern.search(url).group('site') | |
| if key.startswith('Service Worker'): | |
| key = 'Service Worker: ' + \ | |
| pattern.search(key).group('site') | |
| items[key] = p['cpu'] | |
| if key not in process_dict: | |
| process_dict[key] = process_id | |
| process_id += 1 | |
| data.append((ts, items)) | |
| cols = ['timestamp'] + list(process_dict.keys()) | |
| rows = [cols] | |
| # This data is logged every seconds but graph would be too dense. | |
| # So we average data in |avg_window| seconds window. | |
| avg_window = 3 | |
| if len(data) > 1000: | |
| avg_window = 20 | |
| for index, (ts, items) in enumerate(data): | |
| if index % avg_window == 0: | |
| row = [0] * len(cols) | |
| row[0] = ts | |
| for name, cpu in items.items(): | |
| row[process_dict[name]] += cpu / avg_window | |
| if index % avg_window == avg_window - 1: | |
| rows.append(row) | |
| row_indent = ' ' * 12 | |
| data_str = ',\n'.join([row_indent + json.dumps(row) for row in rows]) | |
| out_str = power_dashboard._HTML_CHART_STR.format( | |
| data=data_str, unit='percent', type='process cpu usage') | |
| with open(os.path.join(self.resultsdir, 'task-monitor.html'), | |
| 'w') as f: | |
| f.write(out_str) | |
| def alphanum_key(s): | |
| """ Turn a string into a list of string and numeric chunks. This enables a | |
| sort function to use this list as a key to sort alphanumeric strings | |
| naturally without padding zero digits. | |
| "z23a" -> ["z", 23, "a"] | |
| """ | |
| chunks = re.split('([-.0-9]+)', s) | |
| for i in range(len(chunks)): | |
| try: | |
| chunks[i] = float(chunks[i]) | |
| except ValueError: | |
| pass | |
| return chunks | |
| def _extension_log_handler(handler, form, loop_number): | |
| """ | |
| We use the httpd library to allow us to log whatever we | |
| want from the extension JS script into the log files. | |
| This method is provided to the server as a handler for | |
| all requests that come for the log url in the testServer | |
| unused parameter, because httpd passes the server itself | |
| into the handler. | |
| """ | |
| if form: | |
| for field in sorted(list(form.keys()), key=alphanum_key): | |
| logging.debug("[extension] @ %s %s", _loop_prefix(loop_number), | |
| form[field].value) | |
| # we don't want to add url information to our keyvals. | |
| # httpd adds them automatically so we remove them again | |
| if field in handler.server._form_entries: | |
| del handler.server._form_entries[field] | |
| def _extension_page_time_info_handler(handler, form, loop_number, | |
| test_instance): | |
| page_timestamps = [] | |
| stats_ids = ['mean', 'min', 'max', 'std'] | |
| loadtime_measurements = [] | |
| sorted_pagelt = [] | |
| #show up to this number of slow page-loads | |
| num_slow_page_loads = 5 | |
| if not form: | |
| logging.debug("no page time information returned") | |
| return | |
| for field in sorted(form.keys(), key=alphanum_key): | |
| page = json.loads(form[field].value) | |
| url = page['url'] | |
| pstr = "[extension] @ %s url: %s" % (_loop_prefix(loop_number), url) | |
| logging.debug("%s start_time: %d", pstr, page['start_time']) | |
| if page['end_load_time']: | |
| logging.debug("%s end_load_time: %d", pstr, page['end_load_time']) | |
| load_time = page['end_load_time'] - page['start_time'] | |
| loadtime_measurements.append(load_time) | |
| sorted_pagelt.append((url, load_time)) | |
| logging.debug("%s load time: %d ms", pstr, load_time) | |
| logging.debug("%s end_browse_time: %d", pstr, page['end_browse_time']) | |
| page_timestamps.append(page) | |
| # we don't want to add url information to our keyvals. | |
| # httpd adds them automatically so we remove them again | |
| if field in handler.server._form_entries: | |
| del handler.server._form_entries[field] | |
| page_base = _loop_keyname(loop_number, 'web_page_') | |
| for page in page_timestamps: | |
| page_failed = "_failed" | |
| # timestamps from javascript are in milliseconds, change to seconds | |
| scale = 1.0/1000 | |
| if page['end_load_time']: | |
| tagname = page_base + page['url'] + "_load" | |
| test_instance._task_tracker.append((tagname, | |
| page['start_time'] * scale, page['end_load_time'] * scale)) | |
| tagname = page_base + page['url'] + "_browse" | |
| test_instance._task_tracker.append((tagname, | |
| page['end_load_time'] * scale, page['end_browse_time'] * scale)) | |
| page_failed = "" | |
| tagname = page_base + page['url'] + page_failed | |
| test_instance._task_tracker.append((tagname, | |
| page['start_time'] * scale, page['end_browse_time'] * scale)) | |
| loadtime_measurements = numpy.array(loadtime_measurements) | |
| stats_vals = [loadtime_measurements.mean(), loadtime_measurements.min(), | |
| loadtime_measurements.max(),loadtime_measurements.std()] | |
| key_base = 'ext_ms_page_load_time_' | |
| for i in range(len(stats_ids)): | |
| key = key_base + stats_ids[i] | |
| if key in test_instance._tmp_keyvals: | |
| test_instance._tmp_keyvals[key] += "_%.2f" % stats_vals[i] | |
| else: | |
| test_instance._tmp_keyvals[key] = "%.2f" % stats_vals[i] | |
| sorted_pagelt.sort(key=lambda item: item[1], reverse=True) | |
| message = "The %d slowest page-load-times are:\n" % (num_slow_page_loads) | |
| for url, msecs in sorted_pagelt[:num_slow_page_loads]: | |
| message += "\t%s w/ %d ms" % (url, msecs) | |
| logging.debug("%s\n", message) | |
| def _extension_key_values_handler(handler, form, loop_number, | |
| test_instance): | |
| if not form: | |
| logging.debug("no key value information returned") | |
| return | |
| for field in sorted(form.keys(), key=alphanum_key): | |
| keyval_data = json.loads(form[field].value) | |
| # Print each key:value pair and associate it with the data | |
| for key, value in keyval_data.items(): | |
| logging.debug("[extension] @ %s key: %s val: %s", | |
| _loop_prefix(loop_number), key, value) | |
| # Add the key:values to the _tmp_keyvals set | |
| test_instance._tmp_keyvals[_loop_keyname(loop_number, key)] = value | |
| # we don't want to add url information to our keyvals. | |
| # httpd adds them automatically so we remove them again | |
| if field in handler.server._form_entries: | |
| del handler.server._form_entries[field] | |
| def _loop_prefix(loop): | |
| return "loop%02d" % loop | |
| def _loop_keyname(loop, keyname): | |
| if loop != None: | |
| return "%s_%s" % (_loop_prefix(loop), keyname) | |
| return keyname |