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