1# Lint as: python2, python3 2# Copyright (c) 2012 The Chromium OS Authors. All rights reserved. 3# Use of this source code is governed by a BSD-style license that can be 4# found in the LICENSE file. 5 6import collections 7import json 8import logging 9import numpy 10import os 11import re 12import time 13 14from autotest_lib.client.bin import utils 15from autotest_lib.client.common_lib import error 16from autotest_lib.client.common_lib import utils as _utils 17from autotest_lib.client.common_lib.cros import arc 18from autotest_lib.client.common_lib.cros import arc_common 19from autotest_lib.client.common_lib.cros import chrome 20from autotest_lib.client.common_lib.cros import power_load_util 21from autotest_lib.client.common_lib.cros.network import interface 22from autotest_lib.client.common_lib.cros.network import xmlrpc_datatypes 23from autotest_lib.client.common_lib.cros.network import xmlrpc_security_types 24from autotest_lib.client.cros import backchannel 25from autotest_lib.client.cros import httpd 26from autotest_lib.client.cros import memory_bandwidth_logger 27from autotest_lib.client.cros import service_stopper 28from autotest_lib.client.cros.audio import audio_helper 29from autotest_lib.client.cros.networking import cellular_proxy 30from autotest_lib.client.cros.networking import shill_proxy 31from autotest_lib.client.cros.networking import wifi_proxy 32from autotest_lib.client.cros.power import power_dashboard 33from autotest_lib.client.cros.power import power_status 34from autotest_lib.client.cros.power import power_utils 35from autotest_lib.client.cros.power import force_discharge_utils 36from telemetry.core import exceptions 37 38params_dict = { 39 'test_time_ms': '_mseconds', 40 'should_scroll': '_should_scroll', 41 'should_scroll_up': '_should_scroll_up', 42 'scroll_loop': '_scroll_loop', 43 'scroll_interval_ms': '_scroll_interval_ms', 44 'scroll_by_pixels': '_scroll_by_pixels', 45 'tasks': '_tasks', 46} 47 48class power_LoadTest(arc.ArcTest): 49 """test class""" 50 version = 2 51 52 def initialize(self, 53 percent_initial_charge_min=None, 54 check_network=True, 55 loop_time=3600, 56 loop_count=1, 57 should_scroll='true', 58 should_scroll_up='true', 59 scroll_loop='false', 60 scroll_interval_ms='10000', 61 scroll_by_pixels='600', 62 test_low_batt_p=3, 63 verbose=True, 64 force_wifi=False, 65 wifi_ap='', 66 wifi_sec='none', 67 wifi_pw='', 68 wifi_timeout=60, 69 use_cellular_network=False, 70 tasks='', 71 volume_level=10, 72 mic_gain=10, 73 low_batt_margin_p=2, 74 ac_ok=False, 75 log_mem_bandwidth=False, 76 gaia_login=None, 77 force_discharge='false', 78 pdash_note=''): 79 """ 80 percent_initial_charge_min: min battery charge at start of test 81 check_network: check that Ethernet interface is not running 82 loop_time: length of time to run the test for in each loop 83 loop_count: number of times to loop the test for 84 should_scroll: should the extension scroll pages 85 should_scroll_up: should scroll in up direction 86 scroll_loop: continue scrolling indefinitely 87 scroll_interval_ms: how often to scoll 88 scroll_by_pixels: number of pixels to scroll each time 89 test_low_batt_p: percent battery at which test should stop 90 verbose: add more logging information 91 force_wifi: should we force to test to run on wifi 92 wifi_ap: the name (ssid) of the wifi access point 93 wifi_sec: the type of security for the wifi ap 94 wifi_pw: password for the wifi ap 95 wifi_timeout: The timeout for wifi configuration 96 use_cellular_network: use the cellular network connection instead of wifi 97 volume_level: percent audio volume level 98 mic_gain: percent audio microphone gain level 99 low_batt_margin_p: percent low battery margin to be added to 100 sys_low_batt_p to guarantee test completes prior to powerd shutdown 101 ac_ok: boolean to allow running on AC 102 log_mem_bandwidth: boolean to log memory bandwidth during the test 103 gaia_login: whether real GAIA login should be attempted. If 'None' 104 (default) then boolean is determined from URL. 105 force_discharge: string of whether to tell ec to discharge battery even 106 when the charger is plugged in. 'false' means no forcing discharge; 107 'true' means forcing discharge and raising an error when it fails; 108 'optional' means forcing discharge when possible but not raising an 109 error when it fails, which is more friendly to devices without a 110 battery. 111 pdash_note: note of the current run to send to power dashboard. 112 """ 113 self._backlight = None 114 self._services = None 115 self._browser = None 116 self._loop_time = loop_time 117 self._loop_count = loop_count 118 self._mseconds = self._loop_time * 1000 119 self._verbose = verbose 120 121 self._sys_low_batt_p = 0. 122 self._sys_low_batt_s = 0. 123 self._test_low_batt_p = test_low_batt_p 124 self._should_scroll = should_scroll 125 self._should_scroll_up = should_scroll_up 126 self._scroll_loop = scroll_loop 127 self._scroll_interval_ms = scroll_interval_ms 128 self._scroll_by_pixels = scroll_by_pixels 129 self._tmp_keyvals = {} 130 self._power_status = None 131 self._force_wifi = force_wifi 132 self._use_cellular_network = use_cellular_network 133 self._testServer = None 134 self._tasks = tasks 135 self._backchannel = None 136 self._shill_proxy = None 137 self._volume_level = volume_level 138 self._mic_gain = mic_gain 139 self._ac_ok = ac_ok 140 self._log_mem_bandwidth = log_mem_bandwidth 141 self._wait_time = 60 142 self._stats = collections.defaultdict(list) 143 self._pdash_note = pdash_note 144 145 self._power_status = power_status.get_status() 146 147 self._force_discharge_success = force_discharge_utils.process( 148 force_discharge, self._power_status) 149 if self._force_discharge_success: 150 self._ac_ok = True 151 152 if not self._power_status.battery: 153 if ac_ok and (power_utils.has_powercap_support() or 154 power_utils.has_rapl_support()): 155 logging.info("Device has no battery but has powercap data.") 156 else: 157 rsp = "Skipping test for device without battery and powercap." 158 raise error.TestNAError(rsp) 159 160 self._tmp_keyvals['b_on_ac'] = int(not self._force_discharge_success 161 and self._power_status.on_ac()) 162 self._tmp_keyvals['force_discharge'] = int( 163 self._force_discharge_success) 164 165 self._gaia_login = gaia_login 166 if gaia_login is None: 167 self._gaia_login = power_load_util.use_gaia_login() 168 169 self._username = power_load_util.get_username() 170 self._password = power_load_util.get_password() 171 172 if not self._ac_ok: 173 self._power_status.assert_battery_state(percent_initial_charge_min) 174 175 # If force wifi enabled, convert eth0 to backchannel and connect to the 176 # specified WiFi AP. 177 if self._force_wifi: 178 if self._use_cellular_network: 179 raise error.TestError("Can't force WiFi AP when cellular network" 180 "is used"); 181 182 sec_config = None 183 # TODO(dbasehore): Fix this when we get a better way of figuring out 184 # the wifi security configuration. 185 if wifi_sec == 'rsn' or wifi_sec == 'wpa': 186 sec_config = xmlrpc_security_types.WPAConfig( 187 psk=wifi_pw, 188 wpa_mode=xmlrpc_security_types.WPAConfig.MODE_PURE_WPA2, 189 wpa2_ciphers= 190 [xmlrpc_security_types.WPAConfig.CIPHER_CCMP]) 191 wifi_config = xmlrpc_datatypes.AssociationParameters( 192 ssid=wifi_ap, security_config=sec_config, 193 configuration_timeout=wifi_timeout) 194 # If backchannel is already running, don't run it again. 195 self._backchannel = backchannel.Backchannel() 196 if not self._backchannel.setup(): 197 raise error.TestError('Could not setup Backchannel network.') 198 199 self._shill_proxy = wifi_proxy.WifiProxy() 200 self._shill_proxy.remove_all_wifi_entries() 201 for i in range(1, 4): 202 raw_output = self._shill_proxy.connect_to_wifi_network( 203 wifi_config.ssid, 204 wifi_config.security, 205 wifi_config.security_parameters, 206 wifi_config.save_credentials, 207 station_type=wifi_config.station_type, 208 hidden_network=wifi_config.is_hidden, 209 discovery_timeout_seconds= 210 wifi_config.discovery_timeout, 211 association_timeout_seconds= 212 wifi_config.association_timeout, 213 configuration_timeout_seconds= 214 wifi_config.configuration_timeout * i) 215 result = xmlrpc_datatypes.AssociationResult. \ 216 from_dbus_proxy_output(raw_output) 217 if result.success: 218 break 219 logging.warning('wifi connect: disc:%d assoc:%d config:%d fail:%s', 220 result.discovery_time, result.association_time, 221 result.configuration_time, result.failure_reason) 222 else: 223 raise error.TestError('Could not connect to WiFi network.') 224 225 else: 226 # Find all wired ethernet interfaces. 227 ifaces = [ iface for iface in interface.get_interfaces() 228 if (not iface.is_wifi_device() and 229 iface.name.startswith('eth')) ] 230 logging.debug(str([iface.name for iface in ifaces])) 231 for iface in ifaces: 232 if check_network and iface.is_lower_up: 233 raise error.TestError('Ethernet interface is active. ' + 234 'Please remove Ethernet cable') 235 236 if self._use_cellular_network: 237 self._shill_proxy = cellular_proxy.CellularProxy() 238 cdev = self._shill_proxy.find_cellular_device_object() 239 if cdev is None: 240 raise error.TestError("No cellular device found") 241 242 self._shill_proxy.manager.DisableTechnology( 243 shill_proxy.ShillProxy.TECHNOLOGY_WIFI) 244 245 self._shill_proxy.wait_for_cellular_service_object() 246 247 # record the max backlight level 248 self._backlight = power_utils.Backlight( 249 force_battery=self._force_discharge_success) 250 self._tmp_keyvals['level_backlight_max'] = \ 251 self._backlight.get_max_level() 252 253 self._services = service_stopper.ServiceStopper( 254 service_stopper.ServiceStopper.POWER_DRAW_SERVICES) 255 256 self._detachable_handler = power_utils.BaseActivitySimulator() 257 258 # fix up file perms for the power test extension so that chrome 259 # can access it 260 os.system('chmod -R 755 %s' % self.bindir) 261 262 # setup a HTTP Server to listen for status updates from the power 263 # test extension 264 self._testServer = httpd.HTTPListener(8001, docroot=self.bindir) 265 self._testServer.run() 266 267 # initialize various interesting power related stats 268 self._statomatic = power_status.StatoMatic() 269 270 self._power_status.refresh() 271 self._sys_low_batt_p = float(utils.system_output( 272 'check_powerd_config --low_battery_shutdown_percent')) 273 self._sys_low_batt_s = int(utils.system_output( 274 'check_powerd_config --low_battery_shutdown_time')) 275 276 if self._sys_low_batt_p and self._sys_low_batt_s: 277 raise error.TestError( 278 "Low battery percent and seconds are non-zero.") 279 280 min_low_batt_p = min(self._sys_low_batt_p + low_batt_margin_p, 100) 281 if self._sys_low_batt_p and (min_low_batt_p > self._test_low_batt_p): 282 logging.warning("test low battery threshold is below system " + 283 "low battery requirement. Setting to %f", 284 min_low_batt_p) 285 self._test_low_batt_p = min_low_batt_p 286 287 if self._power_status.battery: 288 self._ah_charge_start = self._power_status.battery.charge_now 289 self._wh_energy_start = self._power_status.battery.energy 290 291 self.task_monitor_file = open(os.path.join(self.resultsdir, 292 'task-monitor.json'), 293 mode='wt', 294 **power_utils.encoding_kwargs()) 295 296 297 def run_once(self): 298 """Test main loop.""" 299 t0 = time.time() 300 301 # record the PSR related info. 302 psr = power_utils.DisplayPanelSelfRefresh(init_time=t0) 303 304 try: 305 self._keyboard_backlight = power_utils.KbdBacklight() 306 self._set_keyboard_backlight_level() 307 except power_utils.KbdBacklightException as e: 308 logging.info("Assuming no keyboard backlight due to :: %s", str(e)) 309 self._keyboard_backlight = None 310 311 self._checkpoint_logger = power_status.CheckpointLogger() 312 seconds_period = 20.0 313 self._meas_logs = power_status.create_measurement_loggers( 314 seconds_period, self._checkpoint_logger) 315 for log in self._meas_logs: 316 log.start() 317 if self._log_mem_bandwidth: 318 self._mlog = memory_bandwidth_logger.MemoryBandwidthLogger( 319 raw=False, seconds_period=2) 320 self._mlog.start() 321 322 # record start time and end time for each task 323 self._task_tracker = [] 324 325 ext_path = os.path.join(os.path.dirname(__file__), 'extension') 326 self._tmp_keyvals['username'] = self._username 327 328 arc_mode = arc_common.ARC_MODE_DISABLED 329 if utils.is_arc_available(): 330 arc_mode = arc_common.ARC_MODE_ENABLED 331 332 # --disable-sync disables test account info sync, eg. Wi-Fi credentials, 333 # so that each test run does not remember info from last test run. 334 extra_browser_args = ['--disable-sync'] 335 # b/228256145 to avoid powerd restart 336 extra_browser_args.append('--disable-features=FirmwareUpdaterApp') 337 try: 338 self._browser = chrome.Chrome( 339 extension_paths=[ext_path], 340 extra_browser_args=extra_browser_args, 341 gaia_login=self._gaia_login, 342 username=self._username, 343 password=self._password, 344 arc_mode=arc_mode) 345 except exceptions.LoginException: 346 # already failed guest login 347 if not self._gaia_login: 348 raise 349 self._gaia_login = False 350 logging.warning("Unable to use GAIA acct %s. Using GUEST instead.\n", 351 self._username) 352 self._browser = chrome.Chrome(extension_paths=[ext_path], 353 gaia_login=self._gaia_login) 354 if not self._gaia_login: 355 self._tmp_keyvals['username'] = 'GUEST' 356 self._tmp_keyvals['gaia_login'] = int(self._gaia_login) 357 358 extension = self._browser.get_extension(ext_path) 359 for k in params_dict: 360 if getattr(self, params_dict[k]) is not '': 361 extension.ExecuteJavaScript('var %s = %s;' % 362 (k, getattr(self, params_dict[k]))) 363 364 # Stop the services after the browser is setup. This ensures that 365 # restart ui does not restart services e.g. powerd underneath us 366 self._services.stop_services() 367 368 # This opens a trap start page to capture tabs opened for first login. 369 # It will be closed when startTest is run. 370 extension.ExecuteJavaScript('chrome.windows.create(null, null);') 371 372 for i in range(self._loop_count): 373 start_time = time.time() 374 extension.ExecuteJavaScript('startTest();') 375 # the power test extension will report its status here 376 latch = self._testServer.add_wait_url('/status') 377 378 # this starts a thread in the server that listens to log 379 # information from the script 380 script_logging = self._testServer.add_wait_url(url='/log') 381 382 # dump any log entry that comes from the script into 383 # the debug log 384 self._testServer.add_url_handler(url='/log',\ 385 handler_func=(lambda handler, forms, loop_counter=i:\ 386 _extension_log_handler(handler, forms, loop_counter))) 387 388 pagetime_tracking = self._testServer.add_wait_url(url='/pagetime') 389 390 self._testServer.add_url_handler(url='/pagetime',\ 391 handler_func=(lambda handler, forms, test_instance=self, 392 loop_counter=i:\ 393 _extension_page_time_info_handler(handler, forms, 394 loop_counter, 395 test_instance))) 396 397 keyvalues_tracking = self._testServer.add_wait_url(url='/keyvalues') 398 399 self._testServer.add_url_handler(url='/keyvalues',\ 400 handler_func=(lambda handler, forms, test_instance=self, 401 loop_counter=i:\ 402 _extension_key_values_handler(handler, forms, 403 loop_counter, 404 test_instance))) 405 self._testServer.add_url(url='/task-monitor') 406 self._testServer.add_url_handler( 407 url='/task-monitor', 408 handler_func=lambda handler, forms: 409 self._extension_task_monitor_handler(handler, forms) 410 ) 411 412 # setup a handler to simulate waking up the base of a detachable 413 # on user interaction. On scrolling, wake for 1s, on page 414 # navigation, wake for 10s. 415 self._testServer.add_url(url='/pagenav') 416 self._testServer.add_url(url='/scroll') 417 418 self._testServer.add_url_handler(url='/pagenav', 419 handler_func=(lambda handler, args, plt=self: 420 plt._detachable_handler.wake_base(10000))) 421 422 self._testServer.add_url_handler(url='/scroll', 423 handler_func=(lambda handler, args, plt=self: 424 plt._detachable_handler.wake_base(1000))) 425 # reset backlight level since powerd might've modified it 426 # based on ambient light 427 self._set_backlight_level(i) 428 self._set_lightbar_level() 429 if self._keyboard_backlight: 430 self._set_keyboard_backlight_level(loop=i) 431 audio_helper.set_volume_levels(self._volume_level, 432 self._mic_gain) 433 434 low_battery = self._do_wait(self._verbose, self._loop_time, 435 latch) 436 script_logging.set() 437 pagetime_tracking.set() 438 keyvalues_tracking.set() 439 440 self._log_loop_checkpoint(i, start_time, time.time()) 441 442 if self._verbose: 443 logging.debug('loop %d completed', i) 444 445 if low_battery: 446 logging.info('Exiting due to low battery') 447 break 448 449 # done with logging from the script, so we can collect that thread 450 t1 = time.time() 451 psr.refresh() 452 self._tmp_keyvals['minutes_battery_life_tested'] = (t1 - t0) / 60 453 self._tmp_keyvals.update(psr.get_keyvals()) 454 self._start_time = t0 455 self._end_time = t1 456 457 458 def postprocess_iteration(self): 459 """Postprocess: write keyvals / log and send data to power dashboard.""" 460 def _log_stats(prefix, stats): 461 if not len(stats): 462 return 463 np = numpy.array(stats) 464 logging.debug("%s samples: %d", prefix, len(np)) 465 logging.debug("%s mean: %.2f", prefix, np.mean()) 466 logging.debug("%s stdev: %.2f", prefix, np.std()) 467 logging.debug("%s max: %.2f", prefix, np.max()) 468 logging.debug("%s min: %.2f", prefix, np.min()) 469 470 471 def _log_per_loop_stats(): 472 samples_per_loop = int(self._loop_time / self._wait_time) + 1 473 for kname in self._stats: 474 start_idx = 0 475 loop = 1 476 for end_idx in range(samples_per_loop, len(self._stats[kname]), 477 samples_per_loop): 478 _log_stats("%s loop %d" % (kname, loop), 479 self._stats[kname][start_idx:end_idx]) 480 loop += 1 481 start_idx = end_idx 482 483 484 def _log_all_stats(): 485 for kname in self._stats: 486 _log_stats(kname, self._stats[kname]) 487 488 489 for task, tstart, tend in self._task_tracker: 490 self._checkpoint_logger.checkpoint('_' + task, tstart, tend) 491 492 keyvals = {} 493 for log in self._meas_logs: 494 keyvals.update(log.calc()) 495 keyvals.update(self._statomatic.publish()) 496 497 if self._log_mem_bandwidth: 498 self._mlog.stop() 499 self._mlog.join() 500 501 _log_all_stats() 502 _log_per_loop_stats() 503 504 # record battery stats 505 if self._power_status.battery: 506 keyvals['a_current_now'] = self._power_status.battery.current_now 507 keyvals['ah_charge_full'] = \ 508 self._power_status.battery.charge_full 509 keyvals['ah_charge_full_design'] = \ 510 self._power_status.battery.charge_full_design 511 keyvals['ah_charge_start'] = self._ah_charge_start 512 keyvals['ah_charge_now'] = self._power_status.battery.charge_now 513 keyvals['ah_charge_used'] = keyvals['ah_charge_start'] - \ 514 keyvals['ah_charge_now'] 515 keyvals['wh_energy_start'] = self._wh_energy_start 516 keyvals['wh_energy_now'] = self._power_status.battery.energy 517 keyvals['wh_energy_used'] = keyvals['wh_energy_start'] - \ 518 keyvals['wh_energy_now'] 519 keyvals['v_voltage_min_design'] = \ 520 self._power_status.battery.voltage_min_design 521 keyvals['wh_energy_full_design'] = \ 522 self._power_status.battery.energy_full_design 523 keyvals['v_voltage_now'] = self._power_status.battery.voltage_now 524 525 keyvals.update(self._tmp_keyvals) 526 527 keyvals['percent_sys_low_battery'] = self._sys_low_batt_p 528 keyvals['seconds_sys_low_battery'] = self._sys_low_batt_s 529 voltage_np = numpy.array(self._stats['v_voltage_now']) 530 voltage_mean = voltage_np.mean() 531 keyvals['v_voltage_mean'] = voltage_mean 532 533 keyvals['wh_energy_powerlogger'] = \ 534 self._energy_use_from_powerlogger(keyvals) 535 536 if (self._force_discharge_success or not self._power_status.on_ac() 537 ) and keyvals['ah_charge_used'] > 0: 538 # For full runs, we should use charge to scale for battery life, 539 # since the voltage swing is accounted for. 540 # For short runs, energy will be a better estimate. 541 # TODO(b/188082306): some devices do not provide 542 # 'wh_energy_powerlogger' so use charge in this case to scale for 543 # battery life. 544 if self._loop_count > 1 or keyvals['wh_energy_powerlogger'] <= 0: 545 estimated_reps = (keyvals['ah_charge_full_design'] / 546 keyvals['ah_charge_used']) 547 else: 548 estimated_reps = (keyvals['wh_energy_full_design'] / 549 keyvals['wh_energy_powerlogger']) 550 551 bat_life_scale = estimated_reps * \ 552 ((100 - keyvals['percent_sys_low_battery']) / 100) 553 554 keyvals['minutes_battery_life'] = bat_life_scale * \ 555 keyvals['minutes_battery_life_tested'] 556 # In the case where sys_low_batt_s is non-zero subtract those 557 # minutes from the final extrapolation. 558 if self._sys_low_batt_s: 559 keyvals['minutes_battery_life'] -= self._sys_low_batt_s / 60 560 561 keyvals['a_current_rate'] = keyvals['ah_charge_used'] * 60 / \ 562 keyvals['minutes_battery_life_tested'] 563 keyvals['w_energy_rate'] = keyvals['wh_energy_used'] * 60 / \ 564 keyvals['minutes_battery_life_tested'] 565 if self._gaia_login: 566 self.output_perf_value(description='minutes_battery_life', 567 value=keyvals['minutes_battery_life'], 568 units='minutes', 569 higher_is_better=True) 570 571 minutes_battery_life_tested = keyvals['minutes_battery_life_tested'] 572 573 # TODO(coconutruben): overwrite write_perf_keyvals for all power 574 # tests and replace this once power_LoadTest inherits from power_Test. 575 # Dump all keyvals into debug keyvals. 576 _utils.write_keyval(os.path.join(self.resultsdir, 'debug_keyval'), 577 keyvals) 578 # Avoid polluting the keyvals with non-core domains. 579 core_keyvals = power_utils.get_core_keyvals(keyvals) 580 for key, value in core_keyvals.items(): 581 if re.match(r'percent_[cg]pu(idle|pkg).*_R?C0(_C1)?_time', key): 582 self.output_perf_value(description=key, 583 value=value, 584 units='percent', 585 higher_is_better=False) 586 587 logger = power_dashboard.KeyvalLogger(self._start_time, self._end_time) 588 for key in [ 589 'b_on_ac', 'force_discharge', 'gaia_login', 590 'percent_usb_suspended_time' 591 ]: 592 logger.add_item(key, keyvals[key], 'point', 'perf') 593 594 # Add audio/docs/email/web fail load details to power dashboard and to keyval 595 for task in ('audio', 'docs', 'email', 'web'): 596 key = 'ext_%s_failed_loads' % task 597 if key not in keyvals: 598 continue 599 vals = (int(x) for x in keyvals[key].split('_')) 600 for index, val in enumerate(vals): 601 log_name = 'loop%02d_%s_failed_load' % (index, task) 602 logger.add_item(log_name, val, 'point', 'perf') 603 core_keyvals[log_name] = val 604 605 # Add ext_ms_page_load_time_mean to power dashboard 606 if 'ext_ms_page_load_time_mean' in keyvals: 607 vals = (float(x) 608 for x in keyvals['ext_ms_page_load_time_mean'].split('_')) 609 for index, val in enumerate(vals): 610 log_name = 'loop%02d_ms_page_load_time' % index 611 logger.add_item(log_name, val, 'point', 'perf') 612 613 # Add battery life and power to power dashboard 614 for key in ('minutes_battery_life_tested', 'minutes_battery_life', 615 'w_energy_rate'): 616 if key in keyvals: 617 logger.add_item(key, keyvals[key], 'point', 'perf') 618 619 self._meas_logs.append(logger) 620 621 self.write_perf_keyval(core_keyvals) 622 for log in self._meas_logs: 623 log.save_results(self.resultsdir) 624 self._checkpoint_logger.save_checkpoint_data(self.resultsdir) 625 626 if minutes_battery_life_tested * 60 < self._loop_time : 627 logging.info('Data is less than 1 loop, skip sending to dashboard.') 628 return 629 630 dashboard_factory = power_dashboard.get_dashboard_factory() 631 for log in self._meas_logs: 632 dashboard = dashboard_factory.createDashboard(log, 633 self.tagged_testname, self.resultsdir, note=self._pdash_note) 634 dashboard.upload() 635 636 power_dashboard.generate_parallax_report(self.outputdir) 637 638 def cleanup(self): 639 force_discharge_utils.restore(self._force_discharge_success) 640 if self._backlight: 641 self._backlight.restore() 642 if self._services: 643 self._services.restore_services() 644 audio_helper.set_default_volume_levels() 645 self._detachable_handler.restore() 646 647 if self.task_monitor_file: 648 self.task_monitor_file.close() 649 self._generate_task_monitor_html() 650 651 if self._shill_proxy: 652 if self._force_wifi: 653 # cleanup backchannel interface 654 # Prevent wifi congestion in test lab by forcing machines to forget the 655 # wifi AP we connected to at the start of the test. 656 self._shill_proxy.remove_all_wifi_entries() 657 658 if self._use_cellular_network: 659 self._shill_proxy.manager.EnableTechnology( 660 shill_proxy.ShillProxy.TECHNOLOGY_WIFI) 661 662 if self._backchannel: 663 self._backchannel.teardown() 664 if self._browser: 665 self._browser.close() 666 if self._testServer: 667 self._testServer.stop() 668 669 670 def _do_wait(self, verbose, seconds, latch): 671 latched = False 672 low_battery = False 673 total_time = seconds + self._wait_time 674 elapsed_time = 0 675 676 while elapsed_time < total_time: 677 time.sleep(self._wait_time) 678 elapsed_time += self._wait_time 679 680 self._power_status.refresh() 681 682 if not self._ac_ok and self._power_status.on_ac(): 683 raise error.TestError('Running on AC power now.') 684 685 if self._power_status.battery: 686 if (not self._ac_ok and 687 self._power_status.battery.status != 'Discharging'): 688 raise error.TestFail('The battery is not discharging.') 689 charge_now = self._power_status.battery.charge_now 690 energy_rate = self._power_status.battery.energy_rate 691 voltage_now = self._power_status.battery.voltage_now 692 self._stats['w_energy_rate'].append(energy_rate) 693 self._stats['v_voltage_now'].append(voltage_now) 694 if verbose: 695 logging.debug('ah_charge_now %f', charge_now) 696 logging.debug('w_energy_rate %f', energy_rate) 697 logging.debug('v_voltage_now %f', voltage_now) 698 699 low_battery = (self._power_status.percent_current_charge() < 700 self._test_low_batt_p) 701 702 latched = latch.is_set() 703 704 if latched or low_battery: 705 break 706 707 if latched: 708 # record chrome power extension stats 709 form_data = self._testServer.get_form_entries() 710 logging.debug(form_data) 711 for e in form_data: 712 key = 'ext_' + e 713 if key in self._tmp_keyvals: 714 self._tmp_keyvals[key] += "_%s" % form_data[e] 715 else: 716 self._tmp_keyvals[key] = form_data[e] 717 else: 718 logging.debug("Didn't get status back from power extension") 719 720 return low_battery 721 722 723 def _set_backlight_level(self, loop=None): 724 self._backlight.set_default() 725 # record brightness level 726 self._tmp_keyvals[_loop_keyname(loop, 'level_backlight')] = \ 727 self._backlight.get_level() 728 729 730 def _set_lightbar_level(self, level='off'): 731 """Set lightbar level. 732 733 Args: 734 level: string value to set lightbar to. See ectool for more details. 735 """ 736 rv = utils.system('which ectool', ignore_status=True) 737 if rv: 738 return 739 rv = utils.system('ectool lightbar %s' % level, ignore_status=True) 740 if rv: 741 logging.info('Assuming no lightbar due to non-zero exit status') 742 else: 743 logging.info('Setting lightbar to %s', level) 744 self._tmp_keyvals['level_lightbar_current'] = level 745 746 747 def _has_light_sensor(self): 748 """ 749 Determine if there is a light sensor on the board. 750 751 @returns True if this host has a light sensor or 752 False if it does not. 753 """ 754 # If the command exits with a failure status, 755 # we do not have a light sensor 756 cmd = 'check_powerd_config --ambient_light_sensor' 757 result = utils.run(cmd, ignore_status=True) 758 if result.exit_status: 759 logging.debug('Ambient light sensor not present') 760 return False 761 logging.debug('Ambient light sensor present') 762 return True 763 764 765 def _energy_use_from_powerlogger(self, keyval): 766 """ 767 Calculates the energy use, in Wh, used over the course of the run as 768 reported by the PowerLogger. 769 770 Args: 771 keyval: the dictionary of keyvals containing PowerLogger output 772 773 Returns: 774 energy_wh: total energy used over the course of this run 775 776 """ 777 energy_wh = 0 778 loop = 0 779 while True: 780 duration_key = _loop_keyname(loop, 'system_duration') 781 avg_power_key = _loop_keyname(loop, 'system_pwr_avg') 782 if duration_key not in keyval or avg_power_key not in keyval: 783 break 784 energy_wh += keyval[duration_key] * keyval[avg_power_key] / 3600 785 loop += 1 786 return energy_wh 787 788 789 def _has_hover_detection(self): 790 """ 791 Checks if hover is detected by the device. 792 793 Returns: 794 Returns True if the hover detection support is enabled. 795 Else returns false. 796 """ 797 798 cmd = 'check_powerd_config --hover_detection' 799 result = utils.run(cmd, ignore_status=True) 800 if result.exit_status: 801 logging.debug('Hover not present') 802 return False 803 logging.debug('Hover present') 804 return True 805 806 807 def _set_keyboard_backlight_level(self, loop=None): 808 """ 809 Sets keyboard backlight based on light sensor and hover. 810 These values are based on UMA as mentioned in 811 https://bugs.chromium.org/p/chromium/issues/detail?id=603233#c10 812 813 ALS | hover | keyboard backlight level 814 --------------------------------------- 815 No | No | default 816 --------------------------------------- 817 Yes | No | 40% of default 818 -------------------------------------- 819 No | Yes | System with this configuration does not exist 820 -------------------------------------- 821 Yes | Yes | 30% of default 822 -------------------------------------- 823 824 Here default is no Ambient Light Sensor, no hover, 825 default always-on brightness level. 826 """ 827 828 default_level = self._keyboard_backlight.get_default_level() 829 level_to_set = default_level 830 has_light_sensor = self._has_light_sensor() 831 has_hover = self._has_hover_detection() 832 # TODO(ravisadineni):if (crbug: 603233) becomes default 833 # change this to reflect it. 834 if has_light_sensor and has_hover: 835 level_to_set = (30 * default_level) / 100 836 elif has_light_sensor: 837 level_to_set = (40 * default_level) / 100 838 elif has_hover: 839 logging.warning('Device has hover but no light sensor') 840 841 logging.info('Setting keyboard backlight to %d', level_to_set) 842 self._keyboard_backlight.set_level(level_to_set) 843 keyname = _loop_keyname(loop, 'percent_kbd_backlight') 844 self._tmp_keyvals[keyname] = self._keyboard_backlight.get_percent() 845 846 847 def _log_loop_checkpoint(self, loop, start, end): 848 loop_str = _loop_prefix(loop) 849 self._checkpoint_logger.checkpoint(loop_str, start, end) 850 851 # Don't log section if we run custom tasks. 852 if self._tasks != '': 853 return 854 855 sections = [ 856 ('browsing', (0, 0.6)), 857 ('email', (0.6, 0.8)), 858 ('document', (0.8, 0.9)), 859 ('video', (0.9, 1)), 860 ] 861 862 # Use start time from extension if found by look for google.com start. 863 goog_str = loop_str + '_web_page_www.google.com' 864 for item, start_extension, _ in self._task_tracker: 865 if item == goog_str: 866 if start_extension >= start: 867 start = start_extension 868 break 869 logging.warning('Timestamp from extension (%.2f) is earlier than' 870 'timestamp from autotest (%.2f).', 871 start_extension, start) 872 873 # Use default loop duration for incomplete loop. 874 duration = max(end - start, self._loop_time) 875 876 for section, fractions in sections: 877 s_start, s_end = (start + duration * fraction 878 for fraction in fractions) 879 if s_start > end: 880 break 881 if s_end > end: 882 s_end = end 883 self._checkpoint_logger.checkpoint(section, s_start, s_end) 884 loop_section = '_' + loop_str + '_' + section 885 self._checkpoint_logger.checkpoint(loop_section, s_start, s_end) 886 887 888 def _extension_task_monitor_handler(self, handler, form): 889 """ 890 We use the httpd library to allow us to log chrome processes usage. 891 """ 892 if form: 893 logging.debug("[task-monitor] got %d samples", len(form)) 894 for idx in sorted(form.keys()): 895 json = form[idx].value 896 self.task_monitor_file.write(json) 897 self.task_monitor_file.write(",\n") 898 # we don't want to add url information to our keyvals. 899 # httpd adds them automatically so we remove them again 900 if idx in handler.server._form_entries: 901 del handler.server._form_entries[idx] 902 handler.send_response(200) 903 904 905 def _generate_task_monitor_html(self): 906 json_decoder = json.JSONDecoder() 907 # regex pattern to simplify the url 908 pattern = re.compile(r'.*https?://(www[.])?(?P<site>[^.]*[.][^/]*)') 909 data = [] 910 min_ts = None 911 process_dict = {} 912 process_id = 1 913 with open(os.path.join(self.resultsdir, 'task-monitor.json'), 'r', 914 **power_utils.encoding_kwargs()) as f: 915 json_strs = f.read().splitlines() 916 for json_str in json_strs[1:]: 917 if len(json_str) < 10: 918 continue 919 entry_dict, _ = json_decoder.raw_decode(json_str, 0) 920 if not min_ts: 921 min_ts = entry_dict['timestamp'] 922 ts = (entry_dict['timestamp'] - min_ts) / 1000 923 924 items = {} 925 for p in entry_dict['processes']: 926 if 'cpu' not in p: 927 continue 928 tab = p['tasks'][0] 929 key = tab['title'] 930 if 'tabId' in tab: 931 tabInfo = [ 932 t for t in entry_dict['tabInfo'] 933 if t['tabId'] == tab['tabId'] 934 ] 935 if len(tabInfo) > 0 and 'url' in tabInfo[0]: 936 url = tabInfo[0]['url'] 937 key = 'Tab: ' + pattern.search(url).group('site') 938 939 if key.startswith('Service Worker'): 940 key = 'Service Worker: ' + \ 941 pattern.search(key).group('site') 942 943 items[key] = p['cpu'] 944 if key not in process_dict: 945 process_dict[key] = process_id 946 process_id += 1 947 948 data.append((ts, items)) 949 950 cols = ['timestamp'] + list(process_dict.keys()) 951 rows = [cols] 952 953 # This data is logged every seconds but graph would be too dense. 954 # So we average data in |avg_window| seconds window. 955 avg_window = 3 956 if len(data) > 1000: 957 avg_window = 20 958 959 for index, (ts, items) in enumerate(data): 960 if index % avg_window == 0: 961 row = [0] * len(cols) 962 row[0] = ts 963 for name, cpu in items.items(): 964 row[process_dict[name]] += cpu / avg_window 965 if index % avg_window == avg_window - 1: 966 rows.append(row) 967 968 row_indent = ' ' * 12 969 data_str = ',\n'.join([row_indent + json.dumps(row) for row in rows]) 970 971 out_str = power_dashboard._HTML_CHART_STR.format( 972 data=data_str, unit='percent', type='process cpu usage') 973 974 with open(os.path.join(self.resultsdir, 'task-monitor.html'), 975 'w') as f: 976 f.write(out_str) 977 978 979def alphanum_key(s): 980 """ Turn a string into a list of string and numeric chunks. This enables a 981 sort function to use this list as a key to sort alphanumeric strings 982 naturally without padding zero digits. 983 "z23a" -> ["z", 23, "a"] 984 """ 985 chunks = re.split('([-.0-9]+)', s) 986 for i in range(len(chunks)): 987 try: 988 chunks[i] = float(chunks[i]) 989 except ValueError: 990 pass 991 return chunks 992 993 994def _extension_log_handler(handler, form, loop_number): 995 """ 996 We use the httpd library to allow us to log whatever we 997 want from the extension JS script into the log files. 998 999 This method is provided to the server as a handler for 1000 all requests that come for the log url in the testServer 1001 1002 unused parameter, because httpd passes the server itself 1003 into the handler. 1004 """ 1005 1006 if form: 1007 for field in sorted(list(form.keys()), key=alphanum_key): 1008 logging.debug("[extension] @ %s %s", _loop_prefix(loop_number), 1009 form[field].value) 1010 # we don't want to add url information to our keyvals. 1011 # httpd adds them automatically so we remove them again 1012 if field in handler.server._form_entries: 1013 del handler.server._form_entries[field] 1014 1015 1016def _extension_page_time_info_handler(handler, form, loop_number, 1017 test_instance): 1018 page_timestamps = [] 1019 1020 stats_ids = ['mean', 'min', 'max', 'std'] 1021 loadtime_measurements = [] 1022 sorted_pagelt = [] 1023 #show up to this number of slow page-loads 1024 num_slow_page_loads = 5 1025 1026 if not form: 1027 logging.debug("no page time information returned") 1028 return 1029 1030 for field in sorted(form.keys(), key=alphanum_key): 1031 page = json.loads(form[field].value) 1032 url = page['url'] 1033 1034 pstr = "[extension] @ %s url: %s" % (_loop_prefix(loop_number), url) 1035 logging.debug("%s start_time: %d", pstr, page['start_time']) 1036 1037 if page['end_load_time']: 1038 logging.debug("%s end_load_time: %d", pstr, page['end_load_time']) 1039 1040 load_time = page['end_load_time'] - page['start_time'] 1041 1042 loadtime_measurements.append(load_time) 1043 sorted_pagelt.append((url, load_time)) 1044 1045 logging.debug("%s load time: %d ms", pstr, load_time) 1046 1047 logging.debug("%s end_browse_time: %d", pstr, page['end_browse_time']) 1048 1049 page_timestamps.append(page) 1050 1051 # we don't want to add url information to our keyvals. 1052 # httpd adds them automatically so we remove them again 1053 if field in handler.server._form_entries: 1054 del handler.server._form_entries[field] 1055 1056 page_base = _loop_keyname(loop_number, 'web_page_') 1057 for page in page_timestamps: 1058 page_failed = "_failed" 1059 # timestamps from javascript are in milliseconds, change to seconds 1060 scale = 1.0/1000 1061 if page['end_load_time']: 1062 tagname = page_base + page['url'] + "_load" 1063 test_instance._task_tracker.append((tagname, 1064 page['start_time'] * scale, page['end_load_time'] * scale)) 1065 1066 tagname = page_base + page['url'] + "_browse" 1067 test_instance._task_tracker.append((tagname, 1068 page['end_load_time'] * scale, page['end_browse_time'] * scale)) 1069 1070 page_failed = "" 1071 1072 tagname = page_base + page['url'] + page_failed 1073 test_instance._task_tracker.append((tagname, 1074 page['start_time'] * scale, page['end_browse_time'] * scale)) 1075 1076 loadtime_measurements = numpy.array(loadtime_measurements) 1077 stats_vals = [loadtime_measurements.mean(), loadtime_measurements.min(), 1078 loadtime_measurements.max(),loadtime_measurements.std()] 1079 1080 key_base = 'ext_ms_page_load_time_' 1081 for i in range(len(stats_ids)): 1082 key = key_base + stats_ids[i] 1083 if key in test_instance._tmp_keyvals: 1084 test_instance._tmp_keyvals[key] += "_%.2f" % stats_vals[i] 1085 else: 1086 test_instance._tmp_keyvals[key] = "%.2f" % stats_vals[i] 1087 1088 1089 sorted_pagelt.sort(key=lambda item: item[1], reverse=True) 1090 1091 message = "The %d slowest page-load-times are:\n" % (num_slow_page_loads) 1092 for url, msecs in sorted_pagelt[:num_slow_page_loads]: 1093 message += "\t%s w/ %d ms" % (url, msecs) 1094 1095 logging.debug("%s\n", message) 1096 1097 1098def _extension_key_values_handler(handler, form, loop_number, 1099 test_instance): 1100 if not form: 1101 logging.debug("no key value information returned") 1102 return 1103 1104 for field in sorted(form.keys(), key=alphanum_key): 1105 keyval_data = json.loads(form[field].value) 1106 1107 # Print each key:value pair and associate it with the data 1108 for key, value in keyval_data.items(): 1109 logging.debug("[extension] @ %s key: %s val: %s", 1110 _loop_prefix(loop_number), key, value) 1111 # Add the key:values to the _tmp_keyvals set 1112 test_instance._tmp_keyvals[_loop_keyname(loop_number, key)] = value 1113 1114 # we don't want to add url information to our keyvals. 1115 # httpd adds them automatically so we remove them again 1116 if field in handler.server._form_entries: 1117 del handler.server._form_entries[field] 1118 1119 1120def _loop_prefix(loop): 1121 return "loop%02d" % loop 1122 1123 1124def _loop_keyname(loop, keyname): 1125 if loop != None: 1126 return "%s_%s" % (_loop_prefix(loop), keyname) 1127 return keyname 1128