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