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, logging, numpy, os, tempfile, time 6 from autotest_lib.client.bin import utils, test 7 from autotest_lib.client.common_lib import error 8 from autotest_lib.client.common_lib import file_utils 9 from autotest_lib.client.common_lib.cros import chrome 10 from autotest_lib.client.common_lib.cros.network import xmlrpc_datatypes 11 from autotest_lib.client.common_lib.cros.network import xmlrpc_security_types 12 from autotest_lib.client.cros import backchannel, httpd 13 from autotest_lib.client.cros import memory_bandwidth_logger 14 from autotest_lib.client.cros import power_rapl, power_status, power_utils 15 from autotest_lib.client.cros import service_stopper 16 from autotest_lib.client.cros.audio import audio_helper 17 from autotest_lib.client.cros.networking import wifi_proxy 18 19 params_dict = { 20 'test_time_ms': '_mseconds', 21 'should_scroll': '_should_scroll', 22 'should_scroll_up': '_should_scroll_up', 23 'scroll_loop': '_scroll_loop', 24 'scroll_interval_ms': '_scroll_interval_ms', 25 'scroll_by_pixels': '_scroll_by_pixels', 26 'tasks': '_tasks', 27 } 28 29 30 class power_LoadTest(test.test): 31 """test class""" 32 version = 2 33 _username = 'powerloadtest (at] gmail.com' 34 _pltp_url = 'https://sites.google.com/a/chromium.org/dev/chromium-os' \ 35 '/testing/power-testing/pltp/pltp' 36 37 38 def initialize(self, percent_initial_charge_min=None, 39 check_network=True, loop_time=3600, loop_count=1, 40 should_scroll='true', should_scroll_up='true', 41 scroll_loop='false', scroll_interval_ms='10000', 42 scroll_by_pixels='600', test_low_batt_p=3, 43 verbose=True, force_wifi=False, wifi_ap='', wifi_sec='none', 44 wifi_pw='', wifi_timeout=60, tasks='', kblight_percent=10, 45 volume_level=10, mic_gain=10, low_batt_margin_p=2, 46 ac_ok=False, log_mem_bandwidth=False): 47 """ 48 percent_initial_charge_min: min battery charge at start of test 49 check_network: check that Ethernet interface is not running 50 loop_time: length of time to run the test for in each loop 51 loop_count: number of times to loop the test for 52 should_scroll: should the extension scroll pages 53 should_scroll_up: should scroll in up direction 54 scroll_loop: continue scrolling indefinitely 55 scroll_interval_ms: how often to scoll 56 scroll_by_pixels: number of pixels to scroll each time 57 test_low_batt_p: percent battery at which test should stop 58 verbose: add more logging information 59 force_wifi: should we force to test to run on wifi 60 wifi_ap: the name (ssid) of the wifi access point 61 wifi_sec: the type of security for the wifi ap 62 wifi_pw: password for the wifi ap 63 wifi_timeout: The timeout for wifi configuration 64 kblight_percent: percent brightness of keyboard backlight 65 volume_level: percent audio volume level 66 mic_gain: percent audio microphone gain level 67 low_batt_margin_p: percent low battery margin to be added to 68 sys_low_batt_p to guarantee test completes prior to powerd shutdown 69 ac_ok: boolean to allow running on AC 70 log_mem_bandwidth: boolean to log memory bandwidth during the test 71 """ 72 self._backlight = None 73 self._services = None 74 self._browser = None 75 self._loop_time = loop_time 76 self._loop_count = loop_count 77 self._mseconds = self._loop_time * 1000 78 self._verbose = verbose 79 80 self._sys_low_batt_p = 0. 81 self._sys_low_batt_s = 0. 82 self._test_low_batt_p = test_low_batt_p 83 self._should_scroll = should_scroll 84 self._should_scroll_up = should_scroll_up 85 self._scroll_loop = scroll_loop 86 self._scroll_interval_ms = scroll_interval_ms 87 self._scroll_by_pixels = scroll_by_pixels 88 self._tmp_keyvals = {} 89 self._power_status = power_status.get_status() 90 self._tmp_keyvals['b_on_ac'] = self._power_status.on_ac() 91 self._force_wifi = force_wifi 92 self._testServer = None 93 self._tasks = tasks.replace(' ','') 94 self._backchannel = None 95 self._shill_proxy = None 96 self._kblight_percent = kblight_percent 97 self._volume_level = volume_level 98 self._mic_gain = mic_gain 99 self._ac_ok = ac_ok 100 self._log_mem_bandwidth = log_mem_bandwidth 101 self._wait_time = 60 102 self._stats = collections.defaultdict(list) 103 104 with tempfile.NamedTemporaryFile() as pltp: 105 file_utils.download_file(self._pltp_url, pltp.name) 106 self._password = pltp.read().rstrip() 107 108 if not ac_ok: 109 self._power_status.assert_battery_state(percent_initial_charge_min) 110 # If force wifi enabled, convert eth0 to backchannel and connect to the 111 # specified WiFi AP. 112 if self._force_wifi: 113 sec_config = None 114 # TODO(dbasehore): Fix this when we get a better way of figuring out 115 # the wifi security configuration. 116 if wifi_sec == 'rsn' or wifi_sec == 'wpa': 117 sec_config = xmlrpc_security_types.WPAConfig( 118 psk=wifi_pw, 119 wpa_mode=xmlrpc_security_types.WPAConfig.MODE_PURE_WPA2, 120 wpa2_ciphers= 121 [xmlrpc_security_types.WPAConfig.CIPHER_CCMP]) 122 wifi_config = xmlrpc_datatypes.AssociationParameters( 123 ssid=wifi_ap, security_config=sec_config, 124 configuration_timeout=wifi_timeout) 125 # If backchannel is already running, don't run it again. 126 self._backchannel = backchannel.Backchannel() 127 if not self._backchannel.setup(): 128 raise error.TestError('Could not setup Backchannel network.') 129 130 self._shill_proxy = wifi_proxy.WifiProxy() 131 self._shill_proxy.remove_all_wifi_entries() 132 for i in xrange(1,4): 133 raw_output = self._shill_proxy.connect_to_wifi_network( 134 wifi_config.ssid, 135 wifi_config.security, 136 wifi_config.security_parameters, 137 wifi_config.save_credentials, 138 station_type=wifi_config.station_type, 139 hidden_network=wifi_config.is_hidden, 140 discovery_timeout_seconds= 141 wifi_config.discovery_timeout, 142 association_timeout_seconds= 143 wifi_config.association_timeout, 144 configuration_timeout_seconds= 145 wifi_config.configuration_timeout * i) 146 result = xmlrpc_datatypes.AssociationResult. \ 147 from_dbus_proxy_output(raw_output) 148 if result.success: 149 break 150 logging.warn('wifi connect: disc:%d assoc:%d config:%d fail:%s', 151 result.discovery_time, result.association_time, 152 result.configuration_time, result.failure_reason) 153 else: 154 raise error.TestError('Could not connect to WiFi network.') 155 156 else: 157 # Find all wired ethernet interfaces. 158 # TODO: combine this with code in network_DisableInterface, in a 159 # common library somewhere. 160 ifaces = [ nic.strip() for nic in os.listdir('/sys/class/net/') 161 if ((not os.path.exists('/sys/class/net/' + nic + '/phy80211')) 162 and nic.find('eth') != -1) ] 163 logging.debug(str(ifaces)) 164 for iface in ifaces: 165 if check_network and self._is_network_iface_running(iface): 166 raise error.TestError('Ethernet interface is active. ' + 167 'Please remove Ethernet cable') 168 169 # record the max backlight level 170 self._backlight = power_utils.Backlight() 171 self._tmp_keyvals['level_backlight_max'] = \ 172 self._backlight.get_max_level() 173 174 self._services = service_stopper.ServiceStopper( 175 service_stopper.ServiceStopper.POWER_DRAW_SERVICES) 176 self._services.stop_services() 177 178 # fix up file perms for the power test extension so that chrome 179 # can access it 180 os.system('chmod -R 755 %s' % self.bindir) 181 182 # setup a HTTP Server to listen for status updates from the power 183 # test extension 184 self._testServer = httpd.HTTPListener(8001, docroot=self.bindir) 185 self._testServer.run() 186 187 # initialize various interesting power related stats 188 self._statomatic = power_status.StatoMatic() 189 190 self._power_status.refresh() 191 (self._sys_low_batt_p, self._sys_low_batt_s) = \ 192 self._get_sys_low_batt_values() 193 min_low_batt_p = min(self._sys_low_batt_p + low_batt_margin_p, 100) 194 if self._sys_low_batt_p and (min_low_batt_p > self._test_low_batt_p): 195 logging.warning("test low battery threshold is below system " + 196 "low battery requirement. Setting to %f", 197 min_low_batt_p) 198 self._test_low_batt_p = min_low_batt_p 199 200 self._ah_charge_start = self._power_status.battery[0].charge_now 201 self._wh_energy_start = self._power_status.battery[0].energy 202 203 def run_once(self): 204 t0 = time.time() 205 206 # record the PSR counter 207 psr_t0 = self._get_psr_counter() 208 209 try: 210 kblight = power_utils.KbdBacklight() 211 kblight.set(self._kblight_percent) 212 self._tmp_keyvals['percent_kbd_backlight'] = kblight.get() 213 except power_utils.KbdBacklightException as e: 214 logging.info("Assuming no keyboard backlight due to :: %s", str(e)) 215 kblight = None 216 217 measurements = \ 218 [power_status.SystemPower(self._power_status.battery_path)] 219 if power_utils.has_rapl_support(): 220 measurements += power_rapl.create_rapl() 221 self._plog = power_status.PowerLogger(measurements, seconds_period=20) 222 self._tlog = power_status.TempLogger([], seconds_period=20) 223 self._plog.start() 224 self._tlog.start() 225 if self._log_mem_bandwidth: 226 self._mlog = memory_bandwidth_logger.MemoryBandwidthLogger( 227 raw=False, seconds_period=2) 228 self._mlog.start() 229 230 ext_path = os.path.join(os.path.dirname(__file__), 'extension') 231 self._browser = chrome.Chrome(extension_paths=[ext_path], 232 gaia_login=True, 233 username=self._username, 234 password=self._password) 235 extension = self._browser.get_extension(ext_path) 236 for k in params_dict: 237 if getattr(self, params_dict[k]) is not '': 238 extension.ExecuteJavaScript('var %s = %s;' % 239 (k, getattr(self, params_dict[k]))) 240 241 # This opens a trap start page to capture tabs opened for first login. 242 # It will be closed when startTest is run. 243 extension.ExecuteJavaScript('chrome.windows.create(null, null);') 244 245 for i in range(self._loop_count): 246 start_time = time.time() 247 extension.ExecuteJavaScript('startTest();') 248 # the power test extension will report its status here 249 latch = self._testServer.add_wait_url('/status') 250 251 # reset backlight level since powerd might've modified it 252 # based on ambient light 253 self._set_backlight_level() 254 self._set_lightbar_level() 255 if kblight: 256 kblight.set(self._kblight_percent) 257 audio_helper.set_volume_levels(self._volume_level, 258 self._mic_gain) 259 260 low_battery = self._do_wait(self._verbose, self._loop_time, 261 latch) 262 263 self._plog.checkpoint('loop%d' % (i), start_time) 264 self._tlog.checkpoint('loop%d' % (i), start_time) 265 if self._verbose: 266 logging.debug('loop %d completed', i) 267 268 if low_battery: 269 logging.info('Exiting due to low battery') 270 break 271 272 t1 = time.time() 273 self._tmp_keyvals['minutes_battery_life_tested'] = (t1 - t0) / 60 274 if psr_t0: 275 self._tmp_keyvals['psr_residency'] = \ 276 (self._get_psr_counter() - psr_t0) / (10 * (t1 - t0)) 277 278 279 def postprocess_iteration(self): 280 def _log_stats(prefix, stats): 281 if not len(stats): 282 return 283 np = numpy.array(stats) 284 logging.debug("%s samples: %d", prefix, len(np)) 285 logging.debug("%s mean: %.2f", prefix, np.mean()) 286 logging.debug("%s stdev: %.2f", prefix, np.std()) 287 logging.debug("%s max: %.2f", prefix, np.max()) 288 logging.debug("%s min: %.2f", prefix, np.min()) 289 290 291 def _log_per_loop_stats(): 292 samples_per_loop = self._loop_time / self._wait_time + 1 293 for kname in self._stats: 294 start_idx = 0 295 loop = 1 296 for end_idx in xrange(samples_per_loop, len(self._stats[kname]), 297 samples_per_loop): 298 _log_stats("%s loop %d" % (kname, loop), 299 self._stats[kname][start_idx:end_idx]) 300 loop += 1 301 start_idx = end_idx 302 303 304 def _log_all_stats(): 305 for kname in self._stats: 306 _log_stats(kname, self._stats[kname]) 307 308 309 keyvals = self._plog.calc() 310 keyvals.update(self._tlog.calc()) 311 keyvals.update(self._statomatic.publish()) 312 313 if self._log_mem_bandwidth: 314 self._mlog.stop() 315 self._mlog.join() 316 317 _log_all_stats() 318 _log_per_loop_stats() 319 320 # record battery stats 321 keyvals['a_current_now'] = self._power_status.battery[0].current_now 322 keyvals['ah_charge_full'] = self._power_status.battery[0].charge_full 323 keyvals['ah_charge_full_design'] = \ 324 self._power_status.battery[0].charge_full_design 325 keyvals['ah_charge_start'] = self._ah_charge_start 326 keyvals['ah_charge_now'] = self._power_status.battery[0].charge_now 327 keyvals['ah_charge_used'] = keyvals['ah_charge_start'] - \ 328 keyvals['ah_charge_now'] 329 keyvals['wh_energy_start'] = self._wh_energy_start 330 keyvals['wh_energy_now'] = self._power_status.battery[0].energy 331 keyvals['wh_energy_used'] = keyvals['wh_energy_start'] - \ 332 keyvals['wh_energy_now'] 333 keyvals['v_voltage_min_design'] = \ 334 self._power_status.battery[0].voltage_min_design 335 keyvals['wh_energy_full_design'] = \ 336 self._power_status.battery[0].energy_full_design 337 keyvals['v_voltage_now'] = self._power_status.battery[0].voltage_now 338 339 keyvals.update(self._tmp_keyvals) 340 341 keyvals['percent_sys_low_battery'] = self._sys_low_batt_p 342 keyvals['seconds_sys_low_battery'] = self._sys_low_batt_s 343 voltage_np = numpy.array(self._stats['v_voltage_now']) 344 voltage_mean = voltage_np.mean() 345 keyvals['v_voltage_mean'] = voltage_mean 346 347 keyvals['wh_energy_powerlogger'] = \ 348 self._energy_use_from_powerlogger(keyvals) 349 350 if keyvals['ah_charge_used'] > 0: 351 # For full runs, we should use charge to scale for battery life, 352 # since the voltage swing is accounted for. 353 # For short runs, energy will be a better estimate. 354 if self._loop_count > 1: 355 estimated_reps = (keyvals['ah_charge_full_design'] / 356 keyvals['ah_charge_used']) 357 else: 358 estimated_reps = (keyvals['wh_energy_full_design'] / 359 keyvals['wh_energy_powerlogger']) 360 361 bat_life_scale = estimated_reps * \ 362 ((100 - keyvals['percent_sys_low_battery']) / 100) 363 364 keyvals['minutes_battery_life'] = bat_life_scale * \ 365 keyvals['minutes_battery_life_tested'] 366 # In the case where sys_low_batt_s is non-zero subtract those 367 # minutes from the final extrapolation. 368 if self._sys_low_batt_s: 369 keyvals['minutes_battery_life'] -= self._sys_low_batt_s / 60 370 371 keyvals['a_current_rate'] = keyvals['ah_charge_used'] * 60 / \ 372 keyvals['minutes_battery_life_tested'] 373 keyvals['w_energy_rate'] = keyvals['wh_energy_used'] * 60 / \ 374 keyvals['minutes_battery_life_tested'] 375 self.output_perf_value(description='minutes_battery_life', 376 value=keyvals['minutes_battery_life'], 377 units='minutes') 378 379 self.write_perf_keyval(keyvals) 380 self._plog.save_results(self.resultsdir) 381 self._tlog.save_results(self.resultsdir) 382 383 384 def cleanup(self): 385 if self._backlight: 386 self._backlight.restore() 387 if self._services: 388 self._services.restore_services() 389 390 # cleanup backchannel interface 391 # Prevent wifi congestion in test lab by forcing machines to forget the 392 # wifi AP we connected to at the start of the test. 393 if self._shill_proxy: 394 self._shill_proxy.remove_all_wifi_entries() 395 if self._backchannel: 396 self._backchannel.teardown() 397 if self._browser: 398 self._browser.close() 399 if self._testServer: 400 self._testServer.stop() 401 402 403 def _do_wait(self, verbose, seconds, latch): 404 latched = False 405 low_battery = False 406 total_time = seconds + self._wait_time 407 elapsed_time = 0 408 409 while elapsed_time < total_time: 410 time.sleep(self._wait_time) 411 elapsed_time += self._wait_time 412 413 self._power_status.refresh() 414 charge_now = self._power_status.battery[0].charge_now 415 energy_rate = self._power_status.battery[0].energy_rate 416 voltage_now = self._power_status.battery[0].voltage_now 417 self._stats['w_energy_rate'].append(energy_rate) 418 self._stats['v_voltage_now'].append(voltage_now) 419 if verbose: 420 logging.debug('ah_charge_now %f', charge_now) 421 logging.debug('w_energy_rate %f', energy_rate) 422 logging.debug('v_voltage_now %f', voltage_now) 423 424 low_battery = (self._power_status.percent_current_charge() < 425 self._test_low_batt_p) 426 427 latched = latch.is_set() 428 429 if latched or low_battery: 430 break 431 432 if latched: 433 # record chrome power extension stats 434 form_data = self._testServer.get_form_entries() 435 logging.debug(form_data) 436 for e in form_data: 437 key = 'ext_' + e 438 if key in self._tmp_keyvals: 439 self._tmp_keyvals[key] += "_%s" % form_data[e] 440 else: 441 self._tmp_keyvals[key] = form_data[e] 442 else: 443 logging.debug("Didn't get status back from power extension") 444 445 return low_battery 446 447 448 def _set_backlight_level(self): 449 self._backlight.set_default() 450 # record brightness level 451 self._tmp_keyvals['level_backlight_current'] = \ 452 self._backlight.get_level() 453 454 455 def _set_lightbar_level(self, level='off'): 456 """Set lightbar level. 457 458 Args: 459 level: string value to set lightbar to. See ectool for more details. 460 """ 461 rv = utils.system('which ectool', ignore_status=True) 462 if rv: 463 return 464 rv = utils.system('ectool lightbar %s' % level, ignore_status=True) 465 if rv: 466 logging.info('Assuming no lightbar due to non-zero exit status') 467 else: 468 logging.info('Setting lightbar to %s', level) 469 self._tmp_keyvals['level_lightbar_current'] = level 470 471 472 def _get_sys_low_batt_values(self): 473 """Determine the low battery values for device and return. 474 475 2012/11/01: power manager (powerd.cc) parses parameters in filesystem 476 and outputs a log message like: 477 478 [1101/173837:INFO:powerd.cc(258)] Using low battery time threshold 479 of 0 secs and using low battery percent threshold of 3.5 480 481 It currently checks to make sure that only one of these values is 482 defined. 483 484 Returns: 485 Tuple of (percent, seconds) 486 percent: float of low battery percentage 487 seconds: float of low battery seconds 488 489 """ 490 split_re = 'threshold of' 491 492 powerd_log = '/var/log/power_manager/powerd.LATEST' 493 cmd = 'grep "low battery time" %s' % powerd_log 494 line = utils.system_output(cmd) 495 secs = float(line.split(split_re)[1].split()[0]) 496 percent = float(line.split(split_re)[2].split()[0]) 497 if secs and percent: 498 raise error.TestError("Low battery percent and seconds " + 499 "are non-zero.") 500 return (percent, secs) 501 502 503 def _get_psr_counter(self): 504 """Get the current value of the system PSR counter. 505 This counts the number of milliseconds the system has resided in PSR. 506 507 Returns: 508 count: amount of time PSR has been active since boot in ms, or 509 None if the performance counter can't be read 510 511 """ 512 psr_status_file = '/sys/kernel/debug/dri/0/i915_edp_psr_status' 513 try: 514 count = utils.get_field(utils.read_file(psr_status_file), 515 0, 516 linestart='Performance_Counter:') 517 except IOError: 518 logging.info("Can't find or read PSR status file") 519 return None 520 521 logging.debug("PSR performance counter: %s", count) 522 return int(count) if count else None 523 524 525 def _is_network_iface_running(self, name): 526 """ 527 Checks to see if the interface is running. 528 529 Args: 530 name: name of the interface to check. 531 532 Returns: 533 True if the interface is running. 534 535 """ 536 try: 537 # TODO: Switch to 'ip' (crbug.com/410601). 538 out = utils.system_output('ifconfig %s' % name) 539 except error.CmdError, e: 540 logging.info(e) 541 return False 542 543 return out.find('RUNNING') >= 0 544 545 546 def _energy_use_from_powerlogger(self, keyval): 547 """ 548 Calculates the energy use, in Wh, used over the course of the run as 549 reported by the PowerLogger. 550 551 Args: 552 keyval: the dictionary of keyvals containing PowerLogger output 553 554 Returns: 555 energy_wh: total energy used over the course of this run 556 557 """ 558 energy_wh = 0 559 loop = 0 560 while True: 561 duration_key = 'loop%d_system_duration' % loop 562 avg_power_key = 'loop%d_system_pwr' % loop 563 if duration_key not in keyval or avg_power_key not in keyval: 564 break 565 energy_wh += keyval[duration_key] * keyval[avg_power_key] / 3600 566 loop += 1 567 return energy_wh 568
