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