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 contextlib 7import ctypes 8import fcntl 9import glob 10import itertools 11import json 12import logging 13import math 14import numpy 15import os 16import re 17import struct 18import threading 19import time 20 21from autotest_lib.client.bin import utils 22from autotest_lib.client.common_lib import error, enum 23from autotest_lib.client.common_lib.utils import poll_for_condition_ex 24from autotest_lib.client.cros import kernel_trace 25from autotest_lib.client.cros.power import power_utils 26 27BatteryDataReportType = enum.Enum('CHARGE', 'ENERGY') 28 29# battery data reported at 1e6 scale 30BATTERY_DATA_SCALE = 1e6 31# number of times to retry reading the battery in the case of bad data 32BATTERY_RETRY_COUNT = 3 33# default filename when saving CheckpointLogger data to file 34CHECKPOINT_LOG_DEFAULT_FNAME = 'checkpoint_log.json' 35 36 37class DevStat(object): 38 """ 39 Device power status. This class implements generic status initialization 40 and parsing routines. 41 """ 42 43 def __init__(self, fields, path=None): 44 self.fields = fields 45 self.path = path 46 47 48 def reset_fields(self): 49 """ 50 Reset all class fields to None to mark their status as unknown. 51 """ 52 for field in self.fields.iterkeys(): 53 setattr(self, field, None) 54 55 56 def read_val(self, file_name, field_type): 57 """Read a value from file. 58 """ 59 try: 60 path = file_name 61 if not file_name.startswith('/'): 62 path = os.path.join(self.path, file_name) 63 f = open(path, 'r') 64 out = f.readline().rstrip('\n') 65 val = field_type(out) 66 return val 67 68 except: 69 return field_type(0) 70 71 72 def read_all_vals(self): 73 """Read all values. 74 """ 75 for field, prop in self.fields.iteritems(): 76 if prop[0]: 77 val = self.read_val(prop[0], prop[1]) 78 setattr(self, field, val) 79 80 def update(self): 81 """Update the DevStat. 82 83 Need to implement in subclass. 84 """ 85 pass 86 87class ThermalStatACPI(DevStat): 88 """ 89 ACPI-based thermal status. 90 91 Fields: 92 (All temperatures are in millidegrees Celsius.) 93 94 str enabled: Whether thermal zone is enabled 95 int temp: Current temperature 96 str type: Thermal zone type 97 int num_trip_points: Number of thermal trip points that activate 98 cooling devices 99 int num_points_tripped: Temperature is above this many trip points 100 str trip_point_N_type: Trip point #N's type 101 int trip_point_N_temp: Trip point #N's temperature value 102 int cdevX_trip_point: Trip point o cooling device #X (index) 103 """ 104 105 MAX_TRIP_POINTS = 20 106 107 thermal_fields = { 108 'enabled': ['enabled', str], 109 'temp': ['temp', int], 110 'type': ['type', str], 111 'num_points_tripped': ['', ''] 112 } 113 path = '/sys/class/thermal/thermal_zone*' 114 115 def __init__(self, path=None): 116 # Browse the thermal folder for trip point fields. 117 self.num_trip_points = 0 118 119 thermal_fields = glob.glob(path + '/*') 120 for file in thermal_fields: 121 field = file[len(path + '/'):] 122 if field.find('trip_point') != -1: 123 if field.find('temp'): 124 field_type = int 125 else: 126 field_type = str 127 self.thermal_fields[field] = [field, field_type] 128 129 # Count the number of trip points. 130 if field.find('_type') != -1: 131 self.num_trip_points += 1 132 133 super(ThermalStatACPI, self).__init__(self.thermal_fields, path) 134 self.update() 135 136 def update(self): 137 if not os.path.exists(self.path): 138 return 139 140 self.read_all_vals() 141 self.num_points_tripped = 0 142 143 for field in self.thermal_fields: 144 if field.find('trip_point_') != -1 and field.find('_temp') != -1 \ 145 and self.temp > self.read_val(field, int): 146 self.num_points_tripped += 1 147 logging.info('Temperature trip point #%s tripped.', \ 148 field[len('trip_point_'):field.rfind('_temp')]) 149 150 151class ThermalStatHwmon(DevStat): 152 """ 153 hwmon-based thermal status. 154 155 Fields: 156 int <tname>_temp<num>_input: Current temperature in millidegrees Celsius 157 where: 158 <tname> : name of hwmon device in sysfs 159 <num> : number of temp as some hwmon devices have multiple 160 161 """ 162 path = '/sys/class/hwmon' 163 164 thermal_fields = {} 165 def __init__(self, rootpath=None): 166 if not rootpath: 167 rootpath = self.path 168 for subpath1 in glob.glob('%s/hwmon*' % rootpath): 169 for subpath2 in ['','device/']: 170 gpaths = glob.glob("%s/%stemp*_input" % (subpath1, subpath2)) 171 for gpath in gpaths: 172 bname = os.path.basename(gpath) 173 field_path = os.path.join(subpath1, subpath2, bname) 174 175 tname_path = os.path.join(os.path.dirname(gpath), "name") 176 tname = utils.read_one_line(tname_path) 177 178 field_key = "%s_%s" % (tname, bname) 179 self.thermal_fields[field_key] = [field_path, int] 180 181 super(ThermalStatHwmon, self).__init__(self.thermal_fields, rootpath) 182 self.update() 183 184 def update(self): 185 if not os.path.exists(self.path): 186 return 187 188 self.read_all_vals() 189 190 def read_val(self, file_name, field_type): 191 try: 192 path = os.path.join(self.path, file_name) 193 f = open(path, 'r') 194 out = f.readline() 195 return field_type(out) 196 except: 197 return field_type(0) 198 199 200class ThermalStat(object): 201 """helper class to instantiate various thermal devices.""" 202 def __init__(self): 203 self._thermals = [] 204 self.min_temp = 999999999 205 self.max_temp = -999999999 206 207 thermal_stat_types = [(ThermalStatHwmon.path, ThermalStatHwmon), 208 (ThermalStatACPI.path, ThermalStatACPI)] 209 for thermal_glob_path, thermal_type in thermal_stat_types: 210 try: 211 thermal_path = glob.glob(thermal_glob_path)[0] 212 logging.debug('Using %s for thermal info.', thermal_path) 213 self._thermals.append(thermal_type(thermal_path)) 214 except: 215 logging.debug('Could not find thermal path %s, skipping.', 216 thermal_glob_path) 217 218 219 def get_temps(self): 220 """Get temperature readings. 221 222 Returns: 223 string of temperature readings. 224 """ 225 temp_str = '' 226 for thermal in self._thermals: 227 thermal.update() 228 for kname in thermal.fields: 229 if kname is 'temp' or kname.endswith('_input'): 230 val = getattr(thermal, kname) 231 temp_str += '%s:%d ' % (kname, val) 232 if val > self.max_temp: 233 self.max_temp = val 234 if val < self.min_temp: 235 self.min_temp = val 236 237 238 return temp_str 239 240 241class BatteryStat(DevStat): 242 """ 243 Battery status. 244 245 Fields: 246 247 float charge_full: Last full capacity reached [Ah] 248 float charge_full_design: Full capacity by design [Ah] 249 float charge_now: Remaining charge [Ah] 250 float current_now: Battery discharge rate [A] 251 float energy: Current battery charge [Wh] 252 float energy_full: Last full capacity reached [Wh] 253 float energy_full_design: Full capacity by design [Wh] 254 float energy_rate: Battery discharge rate [W] 255 float power_now: Battery discharge rate [W] 256 float remaining_time: Remaining discharging time [h] 257 float voltage_min_design: Minimum voltage by design [V] 258 float voltage_max_design: Maximum voltage by design [V] 259 float voltage_now: Voltage now [V] 260 """ 261 262 battery_fields = { 263 'status': ['status', str], 264 'charge_full': ['charge_full', float], 265 'charge_full_design': ['charge_full_design', float], 266 'charge_now': ['charge_now', float], 267 'current_now': ['current_now', float], 268 'voltage_min_design': ['voltage_min_design', float], 269 'voltage_max_design': ['voltage_max_design', float], 270 'voltage_now': ['voltage_now', float], 271 'energy': ['energy_now', float], 272 'energy_full': ['energy_full', float], 273 'energy_full_design': ['energy_full_design', float], 274 'power_now': ['power_now', float], 275 'present': ['present', int], 276 'energy_rate': ['', ''], 277 'remaining_time': ['', ''] 278 } 279 280 def __init__(self, path=None): 281 super(BatteryStat, self).__init__(self.battery_fields, path) 282 self.update() 283 284 285 def update(self): 286 for _ in xrange(BATTERY_RETRY_COUNT): 287 try: 288 self._read_battery() 289 return 290 except error.TestError as e: 291 logging.warn(e) 292 for field, prop in self.battery_fields.iteritems(): 293 logging.warn(field + ': ' + repr(getattr(self, field))) 294 continue 295 raise error.TestError('Failed to read battery state') 296 297 298 def _read_battery(self): 299 self.read_all_vals() 300 301 if self.charge_full == 0 and self.energy_full != 0: 302 battery_type = BatteryDataReportType.ENERGY 303 else: 304 battery_type = BatteryDataReportType.CHARGE 305 306 if self.voltage_min_design != 0: 307 voltage_nominal = self.voltage_min_design 308 else: 309 voltage_nominal = self.voltage_now 310 311 if voltage_nominal == 0: 312 raise error.TestError('Failed to determine battery voltage') 313 314 # Since charge data is present, calculate parameters based upon 315 # reported charge data. 316 if battery_type == BatteryDataReportType.CHARGE: 317 self.charge_full = self.charge_full / BATTERY_DATA_SCALE 318 self.charge_full_design = self.charge_full_design / \ 319 BATTERY_DATA_SCALE 320 self.charge_now = self.charge_now / BATTERY_DATA_SCALE 321 322 self.current_now = math.fabs(self.current_now) / \ 323 BATTERY_DATA_SCALE 324 325 self.energy = voltage_nominal * \ 326 self.charge_now / \ 327 BATTERY_DATA_SCALE 328 self.energy_full = voltage_nominal * \ 329 self.charge_full / \ 330 BATTERY_DATA_SCALE 331 self.energy_full_design = voltage_nominal * \ 332 self.charge_full_design / \ 333 BATTERY_DATA_SCALE 334 335 # Charge data not present, so calculate parameters based upon 336 # reported energy data. 337 elif battery_type == BatteryDataReportType.ENERGY: 338 self.charge_full = self.energy_full / voltage_nominal 339 self.charge_full_design = self.energy_full_design / \ 340 voltage_nominal 341 self.charge_now = self.energy / voltage_nominal 342 343 # TODO(shawnn): check if power_now can really be reported 344 # as negative, in the same way current_now can 345 self.current_now = math.fabs(self.power_now) / \ 346 voltage_nominal 347 348 self.energy = self.energy / BATTERY_DATA_SCALE 349 self.energy_full = self.energy_full / BATTERY_DATA_SCALE 350 self.energy_full_design = self.energy_full_design / \ 351 BATTERY_DATA_SCALE 352 353 self.voltage_min_design = self.voltage_min_design / \ 354 BATTERY_DATA_SCALE 355 self.voltage_max_design = self.voltage_max_design / \ 356 BATTERY_DATA_SCALE 357 self.voltage_now = self.voltage_now / \ 358 BATTERY_DATA_SCALE 359 voltage_nominal = voltage_nominal / \ 360 BATTERY_DATA_SCALE 361 362 self.energy_rate = self.voltage_now * self.current_now 363 364 self.remaining_time = 0 365 if self.current_now and self.energy_rate: 366 self.remaining_time = self.energy / self.energy_rate 367 368 if self.charge_full > (self.charge_full_design * 1.5): 369 raise error.TestError('Unreasonable charge_full value') 370 if self.charge_now > (self.charge_full_design * 1.5): 371 raise error.TestError('Unreasonable charge_now value') 372 373 374class LineStatDummy(DevStat): 375 """ 376 Dummy line stat for devices which don't provide power_supply related sysfs 377 interface. 378 """ 379 def __init__(self): 380 self.online = True 381 382 383 def update(self): 384 pass 385 386class LineStat(DevStat): 387 """ 388 Power line status. 389 390 Fields: 391 392 bool online: Line power online 393 """ 394 395 linepower_fields = { 396 'is_online': ['online', int], 397 'status': ['status', str] 398 } 399 400 401 def __init__(self, path=None): 402 super(LineStat, self).__init__(self.linepower_fields, path) 403 logging.debug("line path: %s", path) 404 self.update() 405 406 407 def update(self): 408 self.read_all_vals() 409 self.online = self.is_online == 1 410 411 412class SysStat(object): 413 """ 414 System power status for a given host. 415 416 Fields: 417 418 battery: A BatteryStat object. 419 linepower: A list of LineStat objects. 420 """ 421 psu_types = ['Mains', 'USB', 'USB_ACA', 'USB_C', 'USB_CDP', 'USB_DCP', 422 'USB_PD', 'USB_PD_DRP', 'Unknown'] 423 424 def __init__(self): 425 power_supply_path = '/sys/class/power_supply/*' 426 self.battery = None 427 self.linepower = [] 428 self.thermal = None 429 self.battery_path = None 430 self.linepower_path = [] 431 432 power_supplies = glob.glob(power_supply_path) 433 for path in power_supplies: 434 type_path = os.path.join(path,'type') 435 if not os.path.exists(type_path): 436 continue 437 power_type = utils.read_one_line(type_path) 438 if power_type == 'Battery': 439 scope_path = os.path.join(path,'scope') 440 if (os.path.exists(scope_path) and 441 utils.read_one_line(scope_path) == 'Device'): 442 continue 443 self.battery_path = path 444 elif power_type in self.psu_types: 445 self.linepower_path.append(path) 446 447 if not self.battery_path or not self.linepower_path: 448 logging.warning("System does not provide power sysfs interface") 449 450 self.thermal = ThermalStat() 451 if self.battery_path: 452 self.sys_low_batt_p = float(utils.system_output( 453 'check_powerd_config --low_battery_shutdown_percent', 454 ignore_status=True) or 4.0) 455 456 457 def refresh(self): 458 """ 459 Initialize device power status objects. 460 """ 461 self.linepower = [] 462 463 if self.battery_path: 464 self.battery = BatteryStat(self.battery_path) 465 466 for path in self.linepower_path: 467 self.linepower.append(LineStat(path)) 468 if not self.linepower: 469 self.linepower = [ LineStatDummy() ] 470 471 temp_str = self.thermal.get_temps() 472 if temp_str: 473 logging.info('Temperature reading: %s', temp_str) 474 else: 475 logging.error('Could not read temperature, skipping.') 476 477 478 def on_ac(self): 479 """ 480 Returns true if device is currently running from AC power. 481 """ 482 on_ac = False 483 for linepower in self.linepower: 484 on_ac |= linepower.online 485 486 # Butterfly can incorrectly report AC online for some time after 487 # unplug. Check battery discharge state to confirm. 488 if utils.get_board() == 'butterfly': 489 on_ac &= (not self.battery_discharging()) 490 return on_ac 491 492 493 def battery_charging(self): 494 """ 495 Returns true if battery is currently charging or false otherwise. 496 """ 497 for linepower in self.linepower: 498 if linepower.status == 'Charging': 499 return True 500 501 if not self.battery_path: 502 logging.warn('Unable to determine battery charge status') 503 return False 504 505 return self.battery.status.rstrip() == 'Charging' 506 507 508 def battery_discharging(self): 509 """ 510 Returns true if battery is currently discharging or false otherwise. 511 """ 512 if not self.battery_path: 513 logging.warn('Unable to determine battery discharge status') 514 return False 515 516 return self.battery.status.rstrip() == 'Discharging' 517 518 def battery_full(self): 519 """ 520 Returns true if battery is currently full or false otherwise. 521 """ 522 if not self.battery_path: 523 logging.warn('Unable to determine battery fullness status') 524 return False 525 526 return self.battery.status.rstrip() == 'Full' 527 528 529 def battery_discharge_ok_on_ac(self): 530 """Returns True if battery is ok to discharge on AC presently. 531 532 some devices cycle between charge & discharge above a certain 533 SoC. If AC is charging and SoC > 95% we can safely assume that. 534 """ 535 return self.battery_charging() and (self.percent_current_charge() > 95) 536 537 538 def percent_current_charge(self): 539 """Returns current charge compare to design capacity in percent. 540 """ 541 return self.battery.charge_now * 100 / \ 542 self.battery.charge_full_design 543 544 545 def percent_display_charge(self): 546 """Returns current display charge in percent. 547 """ 548 keyvals = parse_power_supply_info() 549 return float(keyvals['Battery']['display percentage']) 550 551 552 def assert_battery_state(self, percent_initial_charge_min): 553 """Check initial power configuration state is battery. 554 555 Args: 556 percent_initial_charge_min: float between 0 -> 1.00 of 557 percentage of battery that must be remaining. 558 None|0|False means check not performed. 559 560 Raises: 561 TestError: if one of battery assertions fails 562 """ 563 if self.on_ac(): 564 raise error.TestError( 565 'Running on AC power. Please remove AC power cable.') 566 567 percent_initial_charge = self.percent_current_charge() 568 569 if percent_initial_charge_min and percent_initial_charge < \ 570 percent_initial_charge_min: 571 raise error.TestError('Initial charge (%f) less than min (%f)' 572 % (percent_initial_charge, percent_initial_charge_min)) 573 574 def assert_battery_in_range(self, min_level, max_level): 575 """Raise a error.TestFail if the battery level is not in range.""" 576 current_percent = self.percent_display_charge() 577 if not (min_level <= current_percent <= max_level): 578 raise error.TestFail('battery must be in range [{}, {}]'.format( 579 min_level, max_level)) 580 581 def is_low_battery(self, low_batt_margin_p=2.0): 582 """Returns True if battery current charge is low 583 584 @param low_batt_margin_p: percentage of battery that would be added to 585 system low battery level. 586 """ 587 return (self.battery_discharging() and 588 self.percent_current_charge() < self.sys_low_batt_p + 589 low_batt_margin_p) 590 591 592def get_status(): 593 """ 594 Return a new power status object (SysStat). A new power status snapshot 595 for a given host can be obtained by either calling this routine again and 596 constructing a new SysStat object, or by using the refresh method of the 597 SysStat object. 598 """ 599 status = SysStat() 600 status.refresh() 601 return status 602 603 604def poll_for_charging_behavior(behavior, timeout): 605 """ 606 Wait up to |timeout| seconds for the charging behavior to become |behavior|. 607 608 @param behavior: One of 'ON_AC_AND_CHARGING', 609 'ON_AC_AND_NOT_CHARGING', 610 'NOT_ON_AC_AND_NOT_CHARGING'. 611 @param timeout: in seconds. 612 613 @raises: error.TestFail if the behavior does not match in time, or another 614 exception if something else fails along the way. 615 """ 616 ps = get_status() 617 618 def _verify_on_AC_and_charging(): 619 ps.refresh() 620 if not ps.on_ac(): 621 raise error.TestFail('Device is not on AC, but should be') 622 if not ps.battery_charging(): 623 raise error.TestFail('Device is not charging, but should be') 624 return True 625 626 def _verify_on_AC_and_not_charging(): 627 ps.refresh() 628 if not ps.on_ac(): 629 raise error.TestFail('Device is not on AC, but should be') 630 if ps.battery_charging(): 631 raise error.TestFail('Device is charging, but should not be') 632 return True 633 634 def _verify_not_on_AC_and_not_charging(): 635 ps.refresh() 636 if ps.on_ac(): 637 raise error.TestFail('Device is on AC, but should not be') 638 return True 639 640 poll_functions = { 641 'ON_AC_AND_CHARGING' : _verify_on_AC_and_charging, 642 'ON_AC_AND_NOT_CHARGING' : _verify_on_AC_and_not_charging, 643 'NOT_ON_AC_AND_NOT_CHARGING': _verify_not_on_AC_and_not_charging, 644 } 645 poll_for_condition_ex(poll_functions[behavior], 646 timeout=timeout, 647 sleep_interval=1) 648 649class AbstractStats(object): 650 """ 651 Common superclass for measurements of percentages per state over time. 652 653 Public Attributes: 654 incremental: If False, stats returned are from a single 655 _read_stats. Otherwise, stats are from the difference between 656 the current and last refresh. 657 """ 658 659 @staticmethod 660 def to_percent(stats): 661 """ 662 Turns a dict with absolute time values into a dict with percentages. 663 """ 664 total = sum(stats.itervalues()) 665 if total == 0: 666 return {k: 0 for k in stats} 667 return dict((k, v * 100.0 / total) for (k, v) in stats.iteritems()) 668 669 670 @staticmethod 671 def do_diff(new, old): 672 """ 673 Returns a dict with value deltas from two dicts with matching keys. 674 """ 675 return dict((k, new[k] - old.get(k, 0)) for k in new.iterkeys()) 676 677 678 @staticmethod 679 def format_results_percent(results, name, percent_stats): 680 """ 681 Formats autotest result keys to format: 682 percent_<name>_<key>_time 683 """ 684 for key in percent_stats: 685 results['percent_%s_%s_time' % (name, key)] = percent_stats[key] 686 687 688 @staticmethod 689 def format_results_wavg(results, name, wavg): 690 """ 691 Add an autotest result keys to format: wavg_<name> 692 """ 693 if wavg is not None: 694 results['wavg_%s' % (name)] = wavg 695 696 697 def __init__(self, name=None, incremental=True): 698 if not name: 699 raise error.TestFail("Need to name AbstractStats instance please.") 700 self.name = name 701 self.incremental = incremental 702 self._stats = self._read_stats() 703 704 705 def refresh(self): 706 """ 707 Returns dict mapping state names to percentage of time spent in them. 708 """ 709 raw_stats = result = self._read_stats() 710 if self.incremental: 711 result = self.do_diff(result, self._stats) 712 self._stats = raw_stats 713 return self.to_percent(result) 714 715 716 def _automatic_weighted_average(self): 717 """ 718 Turns a dict with absolute times (or percentages) into a weighted 719 average value. 720 """ 721 total = sum(self._stats.itervalues()) 722 if total == 0: 723 return None 724 725 return sum((float(k)*v) / total for (k, v) in self._stats.iteritems()) 726 727 728 def _supports_automatic_weighted_average(self): 729 """ 730 Override! 731 732 Returns True if stats collected can be automatically converted from 733 percent distribution to weighted average. False otherwise. 734 """ 735 return False 736 737 738 def weighted_average(self): 739 """ 740 Return weighted average calculated using the automated average method 741 (if supported) or using a custom method defined by the stat. 742 """ 743 if self._supports_automatic_weighted_average(): 744 return self._automatic_weighted_average() 745 746 return self._weighted_avg_fn() 747 748 749 def _weighted_avg_fn(self): 750 """ 751 Override! Custom weighted average function. 752 753 Returns weighted average as a single floating point value. 754 """ 755 return None 756 757 758 def _read_stats(self): 759 """ 760 Override! Reads the raw data values that shall be measured into a dict. 761 """ 762 raise NotImplementedError('Override _read_stats in the subclass!') 763 764 765CPU_BASE_PATH = '/sys/devices/system/cpu/' 766 767def count_all_cpus(): 768 """ 769 Return count of cpus on system. 770 """ 771 path = '%s/cpu[0-9]*' % CPU_BASE_PATH 772 return len(glob.glob(path)) 773 774def get_online_cpus(): 775 """ 776 Return list of integer cpu numbers that are online. 777 """ 778 cpus = [int(f.split('/')[-1]) for f in glob.iglob('/dev/cpu/[0-9]*')] 779 return frozenset(cpus) 780 781def get_cpus_filepaths_for_suffix(cpus, suffix): 782 """ 783 For each cpu in |cpus| check whether |CPU_BASE_PATH|/cpu%d/|suffix| exists. 784 Return tuple of two lists t: 785 t[0]: all cpu ids where the condition above holds 786 t[1]: all full paths where condition above holds. 787 """ 788 available_cpus = [] 789 available_paths = [] 790 for c in cpus: 791 c_file_path = os.path.join(CPU_BASE_PATH, 'cpu%d' % c, suffix) 792 if os.path.exists(c_file_path): 793 available_cpus.append(c) 794 available_paths.append(c_file_path) 795 return (available_cpus, available_paths) 796 797class CPUFreqStats(AbstractStats): 798 """ 799 CPU Frequency statistics 800 """ 801 MSR_PLATFORM_INFO = 0xce 802 MSR_IA32_MPERF = 0xe7 803 MSR_IA32_APERF = 0xe8 804 805 def __init__(self, cpus=None): 806 name = 'cpufreq' 807 stats_suffix = 'cpufreq/stats/time_in_state' 808 key_suffix = 'cpufreq/scaling_available_frequencies' 809 cpufreq_driver = '/sys/devices/system/cpu/cpu0/cpufreq/scaling_driver' 810 if not cpus: 811 cpus = get_online_cpus() 812 _, self._file_paths = get_cpus_filepaths_for_suffix(cpus, 813 stats_suffix) 814 815 if len(cpus) and len(cpus) < count_all_cpus(): 816 name = '%s_%s' % (name, '_'.join([str(c) for c in cpus])) 817 self._running_intel_pstate = False 818 self._initial_perf = None 819 self._current_perf = None 820 self._max_freq = 0 821 self._cpus = cpus 822 self._available_freqs = set() 823 824 if not self._file_paths: 825 logging.debug('time_in_state file not found') 826 827 # assumes cpufreq driver for CPU0 is the same as the others. 828 freq_driver = utils.read_one_line(cpufreq_driver) 829 if freq_driver == 'intel_pstate': 830 logging.debug('intel_pstate driver active') 831 self._running_intel_pstate = True 832 else: 833 _, cpufreq_key_paths = get_cpus_filepaths_for_suffix(cpus, 834 key_suffix) 835 for path in cpufreq_key_paths: 836 self._available_freqs |= set(int(x) for x in 837 utils.read_file(path).split()) 838 839 super(CPUFreqStats, self).__init__(name=name) 840 841 842 def _read_stats(self): 843 if self._running_intel_pstate: 844 aperf = 0 845 mperf = 0 846 847 for cpu in self._cpus: 848 aperf += utils.rdmsr(self.MSR_IA32_APERF, cpu) 849 mperf += utils.rdmsr(self.MSR_IA32_MPERF, cpu) 850 851 # max_freq is supposed to be the same for all CPUs and remain 852 # constant throughout. So, we set the entry only once. 853 # Note that this is max non-turbo frequency, some CPU can run at 854 # higher turbo frequency in some condition. 855 if not self._max_freq: 856 platform_info = utils.rdmsr(self.MSR_PLATFORM_INFO) 857 mul = platform_info >> 8 & 0xff 858 bclk = utils.get_intel_bclk_khz() 859 self._max_freq = mul * bclk 860 861 if not self._initial_perf: 862 self._initial_perf = (aperf, mperf) 863 864 self._current_perf = (aperf, mperf) 865 866 stats = dict((k, 0) for k in self._available_freqs) 867 for path in self._file_paths: 868 if not os.path.exists(path): 869 logging.debug('%s is not found', path) 870 continue 871 872 data = utils.read_file(path) 873 for line in data.splitlines(): 874 pair = line.split() 875 freq = int(pair[0]) 876 timeunits = int(pair[1]) 877 if freq in stats: 878 stats[freq] += timeunits 879 else: 880 stats[freq] = timeunits 881 return stats 882 883 884 def _supports_automatic_weighted_average(self): 885 return not self._running_intel_pstate 886 887 888 def _weighted_avg_fn(self): 889 if not self._running_intel_pstate: 890 return None 891 892 if self._current_perf[1] != self._initial_perf[1]: 893 # Avg freq = max_freq * aperf_delta / mperf_delta 894 return self._max_freq * \ 895 float(self._current_perf[0] - self._initial_perf[0]) / \ 896 (self._current_perf[1] - self._initial_perf[1]) 897 return 1.0 898 899 900class CPUCStateStats(AbstractStats): 901 """ 902 Base class for C-state residency statistics 903 """ 904 def __init__(self, name, non_c0_stat=''): 905 self._non_c0_stat = non_c0_stat 906 super(CPUCStateStats, self).__init__(name=name) 907 908 909 def to_percent(self, stats): 910 """ 911 Turns a dict with absolute time values into a dict with percentages. 912 Ignore the |non_c0_stat_name| which is aggegate stat in the total count. 913 """ 914 total = sum(v for k, v in stats.iteritems() if k != self._non_c0_stat) 915 if total == 0: 916 return {k: 0 for k in stats} 917 return {k: v * 100.0 / total for k, v in stats.iteritems()} 918 919 920class CPUIdleStats(CPUCStateStats): 921 """ 922 CPU Idle statistics (refresh() will not work with incremental=False!) 923 """ 924 # TODO (snanda): Handle changes in number of c-states due to events such 925 # as ac <-> battery transitions. 926 # TODO (snanda): Handle non-S0 states. Time spent in suspend states is 927 # currently not factored out. 928 def __init__(self, cpus=None): 929 name = 'cpuidle' 930 cpuidle_suffix = 'cpuidle' 931 if not cpus: 932 cpus = get_online_cpus() 933 cpus, self._cpus = get_cpus_filepaths_for_suffix(cpus, cpuidle_suffix) 934 if len(cpus) and len(cpus) < count_all_cpus(): 935 name = '%s_%s' % (name, '_'.join([str(c) for c in cpus])) 936 super(CPUIdleStats, self).__init__(name=name, non_c0_stat='non-C0') 937 938 939 def _read_stats(self): 940 cpuidle_stats = collections.defaultdict(int) 941 epoch_usecs = int(time.time() * 1000 * 1000) 942 for cpu in self._cpus: 943 state_path = os.path.join(cpu, 'state*') 944 states = glob.glob(state_path) 945 cpuidle_stats['C0'] += epoch_usecs 946 947 for state in states: 948 name = utils.read_one_line(os.path.join(state, 'name')) 949 latency = utils.read_one_line(os.path.join(state, 'latency')) 950 951 if not int(latency) and name == 'POLL': 952 # C0 state. Kernel stats aren't right, so calculate by 953 # subtracting all other states from total time (using epoch 954 # timer since we calculate differences in the end anyway). 955 # NOTE: Only x86 lists C0 under cpuidle, ARM does not. 956 continue 957 958 usecs = int(utils.read_one_line(os.path.join(state, 'time'))) 959 cpuidle_stats['C0'] -= usecs 960 961 if name == '<null>': 962 # Kernel race condition that can happen while a new C-state 963 # gets added (e.g. AC->battery). Don't know the 'name' of 964 # the state yet, but its 'time' would be 0 anyway. 965 logging.warning('Read name: <null>, time: %d from %s...' 966 'skipping.', usecs, state) 967 continue 968 969 cpuidle_stats[name] += usecs 970 cpuidle_stats['non-C0'] += usecs 971 972 return cpuidle_stats 973 974 975class CPUPackageStats(CPUCStateStats): 976 """ 977 Package C-state residency statistics for modern Intel CPUs. 978 """ 979 980 ATOM = {'C2': 0x3F8, 'C4': 0x3F9, 'C6': 0x3FA} 981 NEHALEM = {'C3': 0x3F8, 'C6': 0x3F9, 'C7': 0x3FA} 982 SANDY_BRIDGE = {'C2': 0x60D, 'C3': 0x3F8, 'C6': 0x3F9, 'C7': 0x3FA} 983 SILVERMONT = {'C6': 0x3FA} 984 GOLDMONT = {'C2': 0x60D, 'C3': 0x3F8, 'C6': 0x3F9,'C10': 0x632} 985 BROADWELL = {'C2': 0x60D, 'C3': 0x3F8, 'C6': 0x3F9, 'C7': 0x3FA, 986 'C8': 0x630, 'C9': 0x631,'C10': 0x632} 987 988 def __init__(self): 989 def _get_platform_states(): 990 """ 991 Helper to decide what set of microarchitecture-specific MSRs to use. 992 993 Returns: dict that maps C-state name to MSR address, or None. 994 """ 995 cpu_uarch = utils.get_intel_cpu_uarch() 996 997 return { 998 # model groups pulled from Intel SDM, volume 4 999 # Group same package cstate using the older uarch name 1000 # 1001 # TODO(harry.pan): As the keys represent microarchitecture 1002 # names, we could consider to rename the PC state groups 1003 # to avoid ambiguity. 1004 'Airmont': self.SILVERMONT, 1005 'Atom': self.ATOM, 1006 'Broadwell': self.BROADWELL, 1007 'Comet Lake': self.BROADWELL, 1008 'Goldmont': self.GOLDMONT, 1009 'Haswell': self.SANDY_BRIDGE, 1010 'Ice Lake': self.BROADWELL, 1011 'Ivy Bridge': self.SANDY_BRIDGE, 1012 'Ivy Bridge-E': self.SANDY_BRIDGE, 1013 'Kaby Lake': self.BROADWELL, 1014 'Nehalem': self.NEHALEM, 1015 'Sandy Bridge': self.SANDY_BRIDGE, 1016 'Silvermont': self.SILVERMONT, 1017 'Skylake': self.BROADWELL, 1018 'Tiger Lake': self.BROADWELL, 1019 'Westmere': self.NEHALEM, 1020 }.get(cpu_uarch, None) 1021 1022 self._platform_states = _get_platform_states() 1023 super(CPUPackageStats, self).__init__(name='cpupkg', 1024 non_c0_stat='non-C0_C1') 1025 1026 1027 def _read_stats(self): 1028 packages = set() 1029 template = '/sys/devices/system/cpu/cpu%s/topology/physical_package_id' 1030 if not self._platform_states: 1031 return {} 1032 stats = dict((state, 0) for state in self._platform_states) 1033 stats['C0_C1'] = 0 1034 stats['non-C0_C1'] = 0 1035 1036 for cpu in os.listdir('/dev/cpu'): 1037 if not os.path.exists(template % cpu): 1038 continue 1039 package = utils.read_one_line(template % cpu) 1040 if package in packages: 1041 continue 1042 packages.add(package) 1043 1044 stats['C0_C1'] += utils.rdmsr(0x10, cpu) # TSC 1045 for (state, msr) in self._platform_states.iteritems(): 1046 ticks = utils.rdmsr(msr, cpu) 1047 stats[state] += ticks 1048 stats['non-C0_C1'] += ticks 1049 stats['C0_C1'] -= ticks 1050 1051 return stats 1052 1053 1054class DevFreqStats(AbstractStats): 1055 """ 1056 Devfreq device frequency stats. 1057 """ 1058 1059 _DIR = '/sys/class/devfreq' 1060 1061 1062 def __init__(self, f): 1063 """Constructs DevFreqStats Object that track frequency stats 1064 for the path of the given Devfreq device. 1065 1066 The frequencies for devfreq devices are listed in Hz. 1067 1068 Args: 1069 path: the path to the devfreq device 1070 1071 Example: 1072 /sys/class/devfreq/dmc 1073 """ 1074 self._path = os.path.join(self._DIR, f) 1075 if not os.path.exists(self._path): 1076 raise error.TestError('DevFreqStats: devfreq device does not exist') 1077 1078 fname = os.path.join(self._path, 'available_frequencies') 1079 af = utils.read_one_line(fname).strip() 1080 self._available_freqs = sorted(af.split(), key=int) 1081 1082 super(DevFreqStats, self).__init__(name=f) 1083 1084 def _read_stats(self): 1085 stats = dict((freq, 0) for freq in self._available_freqs) 1086 fname = os.path.join(self._path, 'trans_stat') 1087 1088 with open(fname) as fd: 1089 # The lines that contain the time in each frequency start on the 3rd 1090 # line, so skip the first 2 lines. The last line contains the number 1091 # of transitions, so skip that line too. 1092 # The time in each frequency is at the end of the line. 1093 freq_pattern = re.compile(r'\d+(?=:)') 1094 for line in fd.readlines()[2:-1]: 1095 freq = freq_pattern.search(line) 1096 if freq and freq.group() in self._available_freqs: 1097 stats[freq.group()] = int(line.strip().split()[-1]) 1098 1099 return stats 1100 1101 1102class GPUFreqStats(AbstractStats): 1103 """GPU Frequency statistics class. 1104 1105 TODO(tbroch): add stats for other GPUs 1106 """ 1107 1108 _MALI_DEV = '/sys/class/misc/mali0/device' 1109 _MALI_EVENTS = ['mali_dvfs:mali_dvfs_set_clock'] 1110 _MALI_TRACE_CLK_RE = \ 1111 r'kworker.* (\d+\.\d+): mali_dvfs_set_clock: frequency=(\d+)\d{6}' 1112 1113 _I915_ROOT = '/sys/kernel/debug/dri/0' 1114 _I915_EVENTS = ['i915:intel_gpu_freq_change'] 1115 _I915_CLKS_FILES = ['i915_cur_delayinfo', 'i915_frequency_info'] 1116 _I915_TRACE_CLK_RE = \ 1117 r'kworker.* (\d+\.\d+): intel_gpu_freq_change: new_freq=(\d+)' 1118 _I915_CUR_FREQ_RE = r'CAGF:\s+(\d+)MHz' 1119 _I915_MIN_FREQ_RE = r'Lowest \(RPN\) frequency:\s+(\d+)MHz' 1120 _I915_MAX_FREQ_RE = r'Max non-overclocked \(RP0\) frequency:\s+(\d+)MHz' 1121 # There are 6 frequency steps per 100 MHz 1122 _I915_FREQ_STEPS = [0, 17, 33, 50, 67, 83] 1123 1124 _gpu_type = None 1125 1126 1127 def _get_mali_freqs(self): 1128 """Get mali clocks based on kernel version. 1129 1130 For 3.8-3.18: 1131 # cat /sys/class/misc/mali0/device/clock 1132 100000000 1133 # cat /sys/class/misc/mali0/device/available_frequencies 1134 100000000 1135 160000000 1136 266000000 1137 350000000 1138 400000000 1139 450000000 1140 533000000 1141 533000000 1142 1143 For 4.4+: 1144 Tracked in DevFreqStats 1145 1146 Returns: 1147 cur_mhz: string of current GPU clock in mhz 1148 """ 1149 cur_mhz = None 1150 fqs = [] 1151 1152 fname = os.path.join(self._MALI_DEV, 'clock') 1153 if os.path.exists(fname): 1154 cur_mhz = str(int(int(utils.read_one_line(fname).strip()) / 1e6)) 1155 fname = os.path.join(self._MALI_DEV, 'available_frequencies') 1156 with open(fname) as fd: 1157 for ln in fd.readlines(): 1158 freq = int(int(ln.strip()) / 1e6) 1159 fqs.append(str(freq)) 1160 fqs.sort() 1161 1162 self._freqs = fqs 1163 return cur_mhz 1164 1165 1166 def __init__(self, incremental=False): 1167 1168 1169 min_mhz = None 1170 max_mhz = None 1171 cur_mhz = None 1172 events = None 1173 i915_path = None 1174 self._freqs = [] 1175 self._prev_sample = None 1176 self._trace = None 1177 1178 if os.path.exists(self._MALI_DEV) and \ 1179 not os.path.exists(os.path.join(self._MALI_DEV, "devfreq")): 1180 self._set_gpu_type('mali') 1181 else: 1182 for file_name in self._I915_CLKS_FILES: 1183 full_path = os.path.join(self._I915_ROOT, file_name) 1184 if os.path.exists(full_path): 1185 self._set_gpu_type('i915') 1186 i915_path = full_path 1187 break 1188 else: 1189 # We either don't know how to track GPU stats (yet) or the stats 1190 # are tracked in DevFreqStats. 1191 self._set_gpu_type(None) 1192 1193 logging.debug("gpu_type is %s", self._gpu_type) 1194 1195 if self._gpu_type is 'mali': 1196 events = self._MALI_EVENTS 1197 cur_mhz = self._get_mali_freqs() 1198 if self._freqs: 1199 min_mhz = self._freqs[0] 1200 max_mhz = self._freqs[-1] 1201 1202 elif self._gpu_type is 'i915': 1203 events = self._I915_EVENTS 1204 with open(i915_path) as fd: 1205 for ln in fd.readlines(): 1206 logging.debug("ln = %s", ln) 1207 result = re.findall(self._I915_CUR_FREQ_RE, ln) 1208 if result: 1209 cur_mhz = result[0] 1210 continue 1211 result = re.findall(self._I915_MIN_FREQ_RE, ln) 1212 if result: 1213 min_mhz = result[0] 1214 continue 1215 result = re.findall(self._I915_MAX_FREQ_RE, ln) 1216 if result: 1217 max_mhz = result[0] 1218 continue 1219 if min_mhz and max_mhz: 1220 for i in xrange(int(min_mhz), int(max_mhz) + 1): 1221 if i % 100 in self._I915_FREQ_STEPS: 1222 self._freqs.append(str(i)) 1223 1224 logging.debug("cur_mhz = %s, min_mhz = %s, max_mhz = %s", cur_mhz, 1225 min_mhz, max_mhz) 1226 1227 if cur_mhz and min_mhz and max_mhz: 1228 self._trace = kernel_trace.KernelTrace(events=events) 1229 1230 # Not all platforms or kernel versions support tracing. 1231 if not self._trace or not self._trace.is_tracing(): 1232 logging.warning("GPU frequency tracing not enabled.") 1233 else: 1234 self._prev_sample = (cur_mhz, self._trace.uptime_secs()) 1235 logging.debug("Current GPU freq: %s", cur_mhz) 1236 logging.debug("All GPU freqs: %s", self._freqs) 1237 1238 super(GPUFreqStats, self).__init__(name='gpufreq', incremental=incremental) 1239 1240 1241 @classmethod 1242 def _set_gpu_type(cls, gpu_type): 1243 cls._gpu_type = gpu_type 1244 1245 1246 def _read_stats(self): 1247 if self._gpu_type: 1248 return getattr(self, "_%s_read_stats" % self._gpu_type)() 1249 return {} 1250 1251 1252 def _trace_read_stats(self, regexp): 1253 """Read GPU stats from kernel trace outputs. 1254 1255 Args: 1256 regexp: regular expression to match trace output for frequency 1257 1258 Returns: 1259 Dict with key string in mhz and val float in seconds. 1260 """ 1261 if not self._prev_sample: 1262 return {} 1263 1264 stats = dict((k, 0.0) for k in self._freqs) 1265 results = self._trace.read(regexp=regexp) 1266 for (tstamp_str, freq) in results: 1267 tstamp = float(tstamp_str) 1268 1269 # do not reparse lines in trace buffer 1270 if tstamp <= self._prev_sample[1]: 1271 continue 1272 delta = tstamp - self._prev_sample[1] 1273 logging.debug("freq:%s tstamp:%f - %f delta:%f", 1274 self._prev_sample[0], 1275 tstamp, self._prev_sample[1], 1276 delta) 1277 stats[self._prev_sample[0]] += delta 1278 self._prev_sample = (freq, tstamp) 1279 1280 # Do last record 1281 delta = self._trace.uptime_secs() - self._prev_sample[1] 1282 logging.debug("freq:%s tstamp:uptime - %f delta:%f", 1283 self._prev_sample[0], 1284 self._prev_sample[1], delta) 1285 stats[self._prev_sample[0]] += delta 1286 1287 logging.debug("GPU freq percents:%s", stats) 1288 return stats 1289 1290 1291 def _mali_read_stats(self): 1292 """Read Mali GPU stats 1293 1294 Frequencies are reported in Hz, so use a regex that drops the last 6 1295 digits. 1296 1297 Output in trace looks like this: 1298 1299 kworker/u:24-5220 [000] .... 81060.329232: mali_dvfs_set_clock: frequency=400 1300 kworker/u:24-5220 [000] .... 81061.830128: mali_dvfs_set_clock: frequency=350 1301 1302 Returns: 1303 Dict with frequency in mhz as key and float in seconds for time 1304 spent at that frequency. 1305 """ 1306 return self._trace_read_stats(self._MALI_TRACE_CLK_RE) 1307 1308 1309 def _i915_read_stats(self): 1310 """Read i915 GPU stats. 1311 1312 Output looks like this (kernel >= 3.8): 1313 1314 kworker/u:0-28247 [000] .... 259391.579610: intel_gpu_freq_change: new_freq=400 1315 kworker/u:0-28247 [000] .... 259391.581797: intel_gpu_freq_change: new_freq=350 1316 1317 Returns: 1318 Dict with frequency in mhz as key and float in seconds for time 1319 spent at that frequency. 1320 """ 1321 return self._trace_read_stats(self._I915_TRACE_CLK_RE) 1322 1323 1324 def _supports_automatic_weighted_average(self): 1325 return self._gpu_type is not None 1326 1327 1328class USBSuspendStats(AbstractStats): 1329 """ 1330 USB active/suspend statistics (over all devices) 1331 """ 1332 # TODO (snanda): handle hot (un)plugging of USB devices 1333 # TODO (snanda): handle duration counters wraparound 1334 1335 def __init__(self): 1336 usb_stats_path = '/sys/bus/usb/devices/*/power' 1337 self._file_paths = glob.glob(usb_stats_path) 1338 if not self._file_paths: 1339 logging.debug('USB stats path not found') 1340 super(USBSuspendStats, self).__init__(name='usb') 1341 1342 1343 def _read_stats(self): 1344 usb_stats = {'active': 0, 'suspended': 0} 1345 1346 for path in self._file_paths: 1347 active_duration_path = os.path.join(path, 'active_duration') 1348 total_duration_path = os.path.join(path, 'connected_duration') 1349 1350 if not os.path.exists(active_duration_path) or \ 1351 not os.path.exists(total_duration_path): 1352 logging.debug('duration paths do not exist for: %s', path) 1353 continue 1354 1355 active = int(utils.read_file(active_duration_path)) 1356 total = int(utils.read_file(total_duration_path)) 1357 logging.debug('device %s active for %.2f%%', 1358 path, active * 100.0 / total) 1359 1360 usb_stats['active'] += active 1361 usb_stats['suspended'] += total - active 1362 1363 return usb_stats 1364 1365 1366def get_cpu_sibling_groups(): 1367 """ 1368 Get CPU core groups in HMP systems. 1369 1370 In systems with both small core and big core, 1371 returns groups of small and big sibling groups. 1372 """ 1373 siblings_suffix = 'topology/core_siblings_list' 1374 sibling_groups = [] 1375 cpus_processed = set() 1376 cpus, sibling_file_paths = get_cpus_filepaths_for_suffix(get_online_cpus(), 1377 siblings_suffix) 1378 for c, siblings_path in zip(cpus, sibling_file_paths): 1379 if c in cpus_processed: 1380 # This cpu is already part of a sibling group. Skip. 1381 continue 1382 siblings_data = utils.read_file(siblings_path) 1383 sibling_group = set() 1384 for sibling_entry in siblings_data.split(','): 1385 entry_data = sibling_entry.split('-') 1386 sibling_start = sibling_end = int(entry_data[0]) 1387 if len(entry_data) > 1: 1388 sibling_end = int(entry_data[1]) 1389 siblings = set(range(sibling_start, sibling_end + 1)) 1390 sibling_group |= siblings 1391 cpus_processed |= sibling_group 1392 sibling_groups.append(frozenset(sibling_group)) 1393 return tuple(sibling_groups) 1394 1395 1396def get_available_cpu_stats(): 1397 """Return CPUFreq/CPUIdleStats groups by big-small siblings groups.""" 1398 ret = [CPUPackageStats()] 1399 cpu_sibling_groups = get_cpu_sibling_groups() 1400 if not cpu_sibling_groups: 1401 ret.append(CPUFreqStats()) 1402 ret.append(CPUIdleStats()) 1403 for cpu_group in cpu_sibling_groups: 1404 ret.append(CPUFreqStats(cpu_group)) 1405 ret.append(CPUIdleStats(cpu_group)) 1406 if has_rc6_support(): 1407 ret.append(GPURC6Stats()) 1408 return ret 1409 1410 1411class StatoMatic(object): 1412 """Class to aggregate and monitor a bunch of power related statistics.""" 1413 def __init__(self): 1414 self._start_uptime_secs = kernel_trace.KernelTrace.uptime_secs() 1415 self._astats = [USBSuspendStats(), GPUFreqStats(incremental=False)] 1416 self._astats.extend(get_available_cpu_stats()) 1417 if os.path.isdir(DevFreqStats._DIR): 1418 self._astats.extend([DevFreqStats(f) for f in \ 1419 os.listdir(DevFreqStats._DIR)]) 1420 1421 self._disk = DiskStateLogger() 1422 self._disk.start() 1423 1424 1425 def publish(self): 1426 """Publishes results of various statistics gathered. 1427 1428 Returns: 1429 dict with 1430 key = string 'percent_<name>_<key>_time' 1431 value = float in percent 1432 """ 1433 results = {} 1434 tot_secs = kernel_trace.KernelTrace.uptime_secs() - \ 1435 self._start_uptime_secs 1436 for stat_obj in self._astats: 1437 percent_stats = stat_obj.refresh() 1438 logging.debug("pstats = %s", percent_stats) 1439 if stat_obj.name is 'gpu': 1440 # TODO(tbroch) remove this once GPU freq stats have proved 1441 # reliable 1442 stats_secs = sum(stat_obj._stats.itervalues()) 1443 if stats_secs < (tot_secs * 0.9) or \ 1444 stats_secs > (tot_secs * 1.1): 1445 logging.warning('%s stats dont look right. Not publishing.', 1446 stat_obj.name) 1447 continue 1448 new_res = {} 1449 AbstractStats.format_results_percent(new_res, stat_obj.name, 1450 percent_stats) 1451 wavg = stat_obj.weighted_average() 1452 if wavg: 1453 AbstractStats.format_results_wavg(new_res, stat_obj.name, wavg) 1454 1455 results.update(new_res) 1456 1457 new_res = {} 1458 if self._disk.get_error(): 1459 new_res['disk_logging_error'] = str(self._disk.get_error()) 1460 else: 1461 AbstractStats.format_results_percent(new_res, 'disk', 1462 self._disk.result()) 1463 results.update(new_res) 1464 1465 return results 1466 1467 1468class PowerMeasurement(object): 1469 """Class to measure power. 1470 1471 Public attributes: 1472 domain: String name of the power domain being measured. Example is 1473 'system' for total system power 1474 1475 Public methods: 1476 refresh: Performs any power/energy sampling and calculation and returns 1477 power as float in watts. This method MUST be implemented in 1478 subclass. 1479 """ 1480 1481 def __init__(self, domain): 1482 """Constructor.""" 1483 self.domain = domain 1484 1485 1486 def refresh(self): 1487 """Performs any power/energy sampling and calculation. 1488 1489 MUST be implemented in subclass 1490 1491 Returns: 1492 float, power in watts. 1493 """ 1494 raise NotImplementedError("'refresh' method should be implemented in " 1495 "subclass.") 1496 1497 1498def parse_power_supply_info(): 1499 """Parses power_supply_info command output. 1500 1501 Command output from power_manager ( tools/power_supply_info.cc ) looks like 1502 this: 1503 1504 Device: Line Power 1505 path: /sys/class/power_supply/cros_ec-charger 1506 ... 1507 Device: Battery 1508 path: /sys/class/power_supply/sbs-9-000b 1509 ... 1510 1511 """ 1512 rv = collections.defaultdict(dict) 1513 dev = None 1514 for ln in utils.system_output('power_supply_info').splitlines(): 1515 logging.debug("psu: %s", ln) 1516 result = re.findall(r'^Device:\s+(.*)', ln) 1517 if result: 1518 dev = result[0] 1519 continue 1520 result = re.findall(r'\s+(.+):\s+(.+)', ln) 1521 if result and dev: 1522 kname = re.findall(r'(.*)\s+\(\w+\)', result[0][0]) 1523 if kname: 1524 rv[dev][kname[0]] = result[0][1] 1525 else: 1526 rv[dev][result[0][0]] = result[0][1] 1527 1528 return rv 1529 1530 1531class SystemPower(PowerMeasurement): 1532 """Class to measure system power. 1533 1534 TODO(tbroch): This class provides a subset of functionality in BatteryStat 1535 in hopes of minimizing power draw. Investigate whether its really 1536 significant and if not, deprecate. 1537 1538 Private Attributes: 1539 _voltage_file: path to retrieve voltage in uvolts 1540 _current_file: path to retrieve current in uamps 1541 """ 1542 1543 def __init__(self, battery_dir): 1544 """Constructor. 1545 1546 Args: 1547 battery_dir: path to dir containing the files to probe and log. 1548 usually something like /sys/class/power_supply/BAT0/ 1549 """ 1550 super(SystemPower, self).__init__('system') 1551 # Files to log voltage and current from 1552 self._voltage_file = os.path.join(battery_dir, 'voltage_now') 1553 self._current_file = os.path.join(battery_dir, 'current_now') 1554 1555 1556 def refresh(self): 1557 """refresh method. 1558 1559 See superclass PowerMeasurement for details. 1560 """ 1561 keyvals = parse_power_supply_info() 1562 return float(keyvals['Battery']['energy rate']) 1563 1564 1565class CheckpointLogger(object): 1566 """Class to log checkpoint data. 1567 1568 Public attributes: 1569 checkpoint_data: dictionary of (tname, tlist). 1570 tname: String of testname associated with these time intervals 1571 tlist: list of tuples. Tuple contains: 1572 tstart: Float of time when subtest started 1573 tend: Float of time when subtest ended 1574 1575 Public methods: 1576 start: records a start timestamp 1577 checkpoint 1578 checkblock 1579 save_checkpoint_data 1580 load_checkpoint_data 1581 1582 Static methods: 1583 load_checkpoint_data_static 1584 1585 Private attributes: 1586 _start_time: start timestamp for checkpoint logger 1587 """ 1588 1589 def __init__(self): 1590 self.checkpoint_data = collections.defaultdict(list) 1591 self.start() 1592 1593 # If multiple MeasurementLoggers call start() on the same CheckpointLogger, 1594 # the latest one will register start time. 1595 def start(self): 1596 """Set start time for CheckpointLogger.""" 1597 self._start_time = time.time() 1598 1599 @contextlib.contextmanager 1600 def checkblock(self, tname=''): 1601 """Check point for the following block with test tname. 1602 1603 Args: 1604 tname: String of testname associated with this time interval 1605 """ 1606 start_time = time.time() 1607 yield 1608 self.checkpoint(tname, start_time) 1609 1610 def checkpoint(self, tname='', tstart=None, tend=None): 1611 """Check point the times in seconds associated with test tname. 1612 1613 Args: 1614 tname: String of testname associated with this time interval 1615 tstart: Float in seconds of when tname test started. Should be based 1616 off time.time(). If None, use start timestamp for the checkpoint 1617 logger. 1618 tend: Float in seconds of when tname test ended. Should be based 1619 off time.time(). If None, then value computed in the method. 1620 """ 1621 if not tstart and self._start_time: 1622 tstart = self._start_time 1623 if not tend: 1624 tend = time.time() 1625 self.checkpoint_data[tname].append((tstart, tend)) 1626 logging.info('Finished test "%s" between timestamps [%s, %s]', 1627 tname, tstart, tend) 1628 1629 def convert_relative(self, start_time=None): 1630 """Convert data from power_status.CheckpointLogger object to relative 1631 checkpoint data dictionary. Timestamps are converted to time in seconds 1632 since the test started. 1633 1634 Args: 1635 start_time: Float in seconds of the desired start time reference. 1636 Should be based off time.time(). If None, use start timestamp 1637 for the checkpoint logger. 1638 """ 1639 if start_time is None: 1640 start_time = self._start_time 1641 1642 checkpoint_dict = {} 1643 for tname, tlist in self.checkpoint_data.iteritems(): 1644 checkpoint_dict[tname] = [(tstart - start_time, tend - start_time) 1645 for tstart, tend in tlist] 1646 1647 return checkpoint_dict 1648 1649 def save_checkpoint_data(self, resultsdir, fname=CHECKPOINT_LOG_DEFAULT_FNAME): 1650 """Save checkpoint data. 1651 1652 Args: 1653 resultsdir: String, directory to write results to 1654 fname: String, name of file to write results to 1655 """ 1656 fname = os.path.join(resultsdir, fname) 1657 with file(fname, 'wt') as f: 1658 json.dump(self.checkpoint_data, f, indent=4, separators=(',', ': ')) 1659 1660 def load_checkpoint_data(self, resultsdir, 1661 fname=CHECKPOINT_LOG_DEFAULT_FNAME): 1662 """Load checkpoint data. 1663 1664 Args: 1665 resultsdir: String, directory to load results from 1666 fname: String, name of file to load results from 1667 """ 1668 fname = os.path.join(resultsdir, fname) 1669 try: 1670 with open(fname, 'r') as f: 1671 self.checkpoint_data = json.load(f, 1672 object_hook=to_checkpoint_data) 1673 # Set start time to the earliest start timestamp in file. 1674 self._start_time = min( 1675 ts_pair[0] for ts_pair in itertools.chain.from_iterable( 1676 self.checkpoint_data.itervalues())) 1677 except Exception as exc: 1678 logging.warning('Failed to load checkpoint data from json file %s, ' 1679 'see exception: %s', fname, exc) 1680 1681 @staticmethod 1682 def load_checkpoint_data_static(resultsdir, 1683 fname=CHECKPOINT_LOG_DEFAULT_FNAME): 1684 """Load checkpoint data. 1685 1686 Args: 1687 resultsdir: String, directory to load results from 1688 fname: String, name of file to load results from 1689 """ 1690 fname = os.path.join(resultsdir, fname) 1691 with file(fname, 'r') as f: 1692 checkpoint_data = json.load(f) 1693 return checkpoint_data 1694 1695 1696def to_checkpoint_data(json_dict): 1697 """Helper method to translate json object into CheckpointLogger format. 1698 1699 Args: 1700 json_dict: a json object in the format of python dict 1701 Returns: 1702 a defaultdict in CheckpointLogger data format 1703 """ 1704 checkpoint_data = collections.defaultdict(list) 1705 for tname, tlist in json_dict.iteritems(): 1706 checkpoint_data[tname].extend([tuple(ts_pair) for ts_pair in tlist]) 1707 return checkpoint_data 1708 1709 1710def get_checkpoint_logger_from_file(resultsdir, 1711 fname=CHECKPOINT_LOG_DEFAULT_FNAME): 1712 """Create a CheckpointLogger and load checkpoint data from file. 1713 1714 Args: 1715 resultsdir: String, directory to load results from 1716 fname: String, name of file to load results from 1717 Returns: 1718 CheckpointLogger with data from file 1719 """ 1720 checkpoint_logger = CheckpointLogger() 1721 checkpoint_logger.load_checkpoint_data(resultsdir, fname) 1722 return checkpoint_logger 1723 1724 1725class MeasurementLogger(threading.Thread): 1726 """A thread that logs measurement readings. 1727 1728 Example code snippet: 1729 my_logger = MeasurementLogger([Measurement1, Measurement2]) 1730 my_logger.start() 1731 for testname in tests: 1732 # Option 1: use checkblock 1733 with my_logger.checkblock(testname): 1734 # run the test method for testname 1735 1736 # Option 2: use checkpoint 1737 start_time = time.time() 1738 # run the test method for testname 1739 my_logger.checkpoint(testname, start_time) 1740 1741 keyvals = my_logger.calc() 1742 1743 or using CheckpointLogger: 1744 checkpoint_logger = CheckpointLogger() 1745 my_logger = MeasurementLogger([Measurement1, Measurement2], 1746 checkpoint_logger) 1747 my_logger.start() 1748 for testname in tests: 1749 # Option 1: use checkblock 1750 with checkpoint_logger.checkblock(testname): 1751 # run the test method for testname 1752 1753 # Option 2: use checkpoint 1754 start_time = time.time() 1755 # run the test method for testname 1756 checkpoint_logger.checkpoint(testname, start_time) 1757 1758 keyvals = my_logger.calc() 1759 1760 Public attributes: 1761 seconds_period: float, probing interval in seconds. 1762 readings: list of lists of floats of measurements. 1763 times: list of floats of time (since Epoch) of when measurements 1764 occurred. len(time) == len(readings). 1765 done: flag to stop the logger. 1766 domains: list of domain strings being measured 1767 1768 Public methods: 1769 run: launches the thread to gather measurements 1770 refresh: perform data samplings for every measurements 1771 calc: calculates 1772 save_results: 1773 1774 Private attributes: 1775 _measurements: list of Measurement objects to be sampled. 1776 _checkpoint_data: dictionary of (tname, tlist). 1777 tname: String of testname associated with these time intervals 1778 tlist: list of tuples. Tuple contains: 1779 tstart: Float of time when subtest started 1780 tend: Float of time when subtest ended 1781 _results: list of results tuples. Tuple contains: 1782 prefix: String of subtest 1783 mean: Float of mean in watts 1784 std: Float of standard deviation of measurements 1785 tstart: Float of time when subtest started 1786 tend: Float of time when subtest ended 1787 """ 1788 def __init__(self, measurements, seconds_period=1.0, checkpoint_logger=None): 1789 """Initialize a logger. 1790 1791 Args: 1792 _measurements: list of Measurement objects to be sampled. 1793 seconds_period: float, probing interval in seconds. Default 1.0 1794 """ 1795 threading.Thread.__init__(self) 1796 1797 self.seconds_period = seconds_period 1798 1799 self.readings = [] 1800 self.times = [] 1801 1802 self.domains = [] 1803 self._measurements = measurements 1804 for meas in self._measurements: 1805 self.domains.append(meas.domain) 1806 1807 self._checkpoint_logger = \ 1808 checkpoint_logger if checkpoint_logger else CheckpointLogger() 1809 1810 self.done = False 1811 1812 def start(self): 1813 self._checkpoint_logger.start() 1814 super(MeasurementLogger, self).start() 1815 1816 def refresh(self): 1817 """Perform data samplings for every measurements. 1818 1819 Returns: 1820 list of sampled data for every measurements. 1821 """ 1822 readings = [] 1823 for meas in self._measurements: 1824 readings.append(meas.refresh()) 1825 return readings 1826 1827 def run(self): 1828 """Threads run method.""" 1829 loop = 0 1830 start_time = time.time() 1831 while(not self.done): 1832 # TODO (dbasehore): We probably need proper locking in this file 1833 # since there have been race conditions with modifying and accessing 1834 # data. 1835 self.readings.append(self.refresh()) 1836 current_time = time.time() 1837 self.times.append(current_time) 1838 loop += 1 1839 next_measurement_time = start_time + loop * self.seconds_period 1840 time.sleep(next_measurement_time - current_time) 1841 1842 @contextlib.contextmanager 1843 def checkblock(self, tname=''): 1844 """Check point for the following block with test tname. 1845 1846 Args: 1847 tname: String of testname associated with this time interval 1848 """ 1849 start_time = time.time() 1850 yield 1851 self.checkpoint(tname, start_time) 1852 1853 def checkpoint(self, tname='', tstart=None, tend=None): 1854 """Just a thin method calling the CheckpointLogger checkpoint method. 1855 1856 Args: 1857 tname: String of testname associated with this time interval 1858 tstart: Float in seconds of when tname test started. Should be based 1859 off time.time() 1860 tend: Float in seconds of when tname test ended. Should be based 1861 off time.time(). If None, then value computed in the method. 1862 """ 1863 self._checkpoint_logger.checkpoint(tname, tstart, tend) 1864 1865 # TODO(seankao): It might be useful to pull this method to CheckpointLogger, 1866 # to allow checkpoint usage without an explicit MeasurementLogger. 1867 def calc(self, mtype=None): 1868 """Calculate average measurement during each of the sub-tests. 1869 1870 Method performs the following steps: 1871 1. Signals the thread to stop running. 1872 2. Calculates mean, max, min, count on the samples for each of the 1873 measurements. 1874 3. Stores results to be written later. 1875 4. Creates keyvals for autotest publishing. 1876 1877 Args: 1878 mtype: string of measurement type. For example: 1879 pwr == power 1880 temp == temperature 1881 Returns: 1882 dict of keyvals suitable for autotest results. 1883 """ 1884 if not mtype: 1885 mtype = 'meas' 1886 1887 t = numpy.array(self.times) 1888 keyvals = {} 1889 results = [('domain', 'mean', 'std', 'duration (s)', 'start ts', 1890 'end ts')] 1891 # TODO(coconutruben): ensure that values is meaningful i.e. go through 1892 # the Loggers and add a unit attribute to each so that the raw 1893 # data is readable. 1894 raw_results = [('domain', 'values (%s)' % mtype)] 1895 1896 if not self.done: 1897 self.done = True 1898 # times 2 the sleep time in order to allow for readings as well. 1899 self.join(timeout=self.seconds_period * 2) 1900 1901 if not self._checkpoint_logger.checkpoint_data: 1902 self._checkpoint_logger.checkpoint() 1903 1904 for i, domain_readings in enumerate(zip(*self.readings)): 1905 meas = numpy.array(domain_readings) 1906 domain = self.domains[i] 1907 1908 for tname, tlist in self._checkpoint_logger.checkpoint_data.iteritems(): 1909 if tname: 1910 prefix = '%s_%s' % (tname, domain) 1911 else: 1912 prefix = domain 1913 keyvals[prefix+'_duration'] = 0 1914 # Select all readings taken between tstart and tend 1915 # timestamps in tlist. 1916 masks = [] 1917 for tstart, tend in tlist: 1918 keyvals[prefix+'_duration'] += tend - tstart 1919 # Try block just in case 1920 # code.google.com/p/chromium/issues/detail?id=318892 1921 # is not fixed. 1922 try: 1923 masks.append(numpy.logical_and(tstart < t, t < tend)) 1924 except ValueError, e: 1925 logging.debug('Error logging measurements: %s', str(e)) 1926 logging.debug('timestamps %d %s', t.len, t) 1927 logging.debug('timestamp start, end %f %f', tstart, tend) 1928 logging.debug('measurements %d %s', meas.len, meas) 1929 mask = numpy.logical_or.reduce(masks) 1930 meas_array = meas[mask] 1931 1932 # If sub-test terminated early, avoid calculating avg, std and 1933 # min 1934 if not meas_array.size: 1935 continue 1936 meas_mean = meas_array.mean() 1937 meas_std = meas_array.std() 1938 1939 # Results list can be used for pretty printing and saving as csv 1940 # TODO(seankao): new results format? 1941 result = (prefix, meas_mean, meas_std) 1942 for tstart, tend in tlist: 1943 result = result + (tend - tstart, tstart, tend) 1944 results.append(result) 1945 raw_results.append((prefix,) + tuple(meas_array.tolist())) 1946 1947 keyvals[prefix + '_' + mtype + '_avg'] = meas_mean 1948 keyvals[prefix + '_' + mtype + '_cnt'] = meas_array.size 1949 keyvals[prefix + '_' + mtype + '_max'] = meas_array.max() 1950 keyvals[prefix + '_' + mtype + '_min'] = meas_array.min() 1951 keyvals[prefix + '_' + mtype + '_std'] = meas_std 1952 self._results = results 1953 self._raw_results = raw_results 1954 return keyvals 1955 1956 1957 def save_results(self, resultsdir, fname_prefix=None): 1958 """Save computed results in a nice tab-separated format. 1959 This is useful for long manual runs. 1960 1961 Args: 1962 resultsdir: String, directory to write results to 1963 fname_prefix: prefix to use for fname. If provided outfiles 1964 will be [fname]_[raw|summary].txt 1965 """ 1966 if not fname_prefix: 1967 fname_prefix = 'meas_results_%.0f' % time.time() 1968 fname = '%s_summary.txt' % fname_prefix 1969 raw_fname = fname.replace('summary', 'raw') 1970 for name, data in [(fname, self._results), 1971 (raw_fname, self._raw_results)]: 1972 with open(os.path.join(resultsdir, name), 'wt') as f: 1973 # First row contains the headers 1974 f.write('%s\n' % '\t'.join(data[0])) 1975 for row in data[1:]: 1976 # First column name, rest are numbers. See _calc_power() 1977 fmt_row = [row[0]] + ['%.2f' % x for x in row[1:]] 1978 f.write('%s\n' % '\t'.join(fmt_row)) 1979 1980 1981class CPUStatsLogger(MeasurementLogger): 1982 """Class to measure CPU Frequency and CPU Idle Stats. 1983 1984 CPUStatsLogger derived from MeasurementLogger class but overload data 1985 samplings method because MeasurementLogger assumed that each sampling is 1986 independent to each other. However, in this case it is not. For example, 1987 CPU time spent in C0 state is measure by time not spent in all other states. 1988 1989 CPUStatsLogger also collects the weight average in each time period if the 1990 underlying AbstractStats support weight average function. 1991 1992 Private attributes: 1993 _stats: list of CPU AbstractStats objects to be sampled. 1994 _refresh_count: number of times refresh() has been called. 1995 _last_wavg: dict of wavg when refresh() was last called. 1996 """ 1997 def __init__(self, seconds_period=1.0, checkpoint_logger=None): 1998 """Initialize a CPUStatsLogger. 1999 2000 Args: 2001 seconds_period: float, probing interval in seconds. Default 1.0 2002 """ 2003 # We don't use measurements since CPU stats can't measure separately. 2004 super(CPUStatsLogger, self).__init__([], seconds_period, checkpoint_logger) 2005 2006 self._stats = get_available_cpu_stats() 2007 self._stats.append(GPUFreqStats()) 2008 self.domains = [] 2009 for stat in self._stats: 2010 self.domains.extend([stat.name + '_' + str(state_name) 2011 for state_name in stat.refresh()]) 2012 if stat.weighted_average(): 2013 self.domains.append('wavg_' + stat.name) 2014 self._refresh_count = 0 2015 self._last_wavg = collections.defaultdict(int) 2016 2017 def refresh(self): 2018 self._refresh_count += 1 2019 count = self._refresh_count 2020 ret = [] 2021 for stat in self._stats: 2022 ret.extend(stat.refresh().values()) 2023 wavg = stat.weighted_average() 2024 if wavg: 2025 if stat.incremental: 2026 last_wavg = self._last_wavg[stat.name] 2027 self._last_wavg[stat.name] = wavg 2028 # Calculate weight average in this period using current 2029 # total weight average and last total weight average. 2030 # The result will lose some precision with higher number of 2031 # count but still good enough for 11 significant digits even 2032 # if we logged the data every 1 second for a day. 2033 ret.append(wavg * count - last_wavg * (count - 1)) 2034 else: 2035 ret.append(wavg) 2036 return ret 2037 2038 def save_results(self, resultsdir, fname_prefix=None): 2039 if not fname_prefix: 2040 fname_prefix = 'cpu_results_%.0f' % time.time() 2041 super(CPUStatsLogger, self).save_results(resultsdir, fname_prefix) 2042 2043 2044class PowerLogger(MeasurementLogger): 2045 """Class to measure power consumption. 2046 """ 2047 def save_results(self, resultsdir, fname_prefix=None): 2048 if not fname_prefix: 2049 fname_prefix = 'power_results_%.0f' % time.time() 2050 super(PowerLogger, self).save_results(resultsdir, fname_prefix) 2051 2052 2053 def calc(self, mtype='pwr'): 2054 return super(PowerLogger, self).calc(mtype) 2055 2056 2057class TempMeasurement(object): 2058 """Class to measure temperature. 2059 2060 Public attributes: 2061 domain: String name of the temperature domain being measured. Example is 2062 'cpu' for cpu temperature 2063 2064 Private attributes: 2065 _path: Path to temperature file to read ( in millidegrees Celsius ) 2066 2067 Public methods: 2068 refresh: Performs any temperature sampling and calculation and returns 2069 temperature as float in degrees Celsius. 2070 """ 2071 def __init__(self, domain, path): 2072 """Constructor.""" 2073 self.domain = domain 2074 self._path = path 2075 2076 2077 def refresh(self): 2078 """Performs temperature 2079 2080 Returns: 2081 float, temperature in degrees Celsius 2082 """ 2083 return int(utils.read_one_line(self._path)) / 1000. 2084 2085 2086class BatteryTempMeasurement(TempMeasurement): 2087 """Class to measure battery temperature.""" 2088 def __init__(self): 2089 super(BatteryTempMeasurement, self).__init__('battery', 'battery_temp') 2090 2091 2092 def refresh(self): 2093 """Perform battery temperature reading. 2094 2095 Returns: 2096 float, temperature in degrees Celsius. 2097 """ 2098 result = utils.run(self._path, timeout=5, ignore_status=True) 2099 return float(result.stdout) 2100 2101 2102def has_battery_temp(): 2103 """Determine if DUT can provide battery temperature. 2104 2105 Returns: 2106 Boolean, True if battery temperature available. False otherwise. 2107 """ 2108 if not power_utils.has_battery(): 2109 return False 2110 2111 btemp = BatteryTempMeasurement() 2112 try: 2113 btemp.refresh() 2114 except ValueError: 2115 return False 2116 2117 return True 2118 2119 2120class TempLogger(MeasurementLogger): 2121 """A thread that logs temperature readings in millidegrees Celsius.""" 2122 def __init__(self, measurements, seconds_period=30.0, checkpoint_logger=None): 2123 if not measurements: 2124 domains = set() 2125 measurements = [] 2126 tstats = ThermalStatHwmon() 2127 for kname in tstats.fields: 2128 match = re.match(r'(\S+)_temp(\d+)_input', kname) 2129 if not match: 2130 continue 2131 domain = match.group(1) + '-t' + match.group(2) 2132 fpath = tstats.fields[kname][0] 2133 new_meas = TempMeasurement(domain, fpath) 2134 measurements.append(new_meas) 2135 domains.add(domain) 2136 2137 if has_battery_temp(): 2138 measurements.append(BatteryTempMeasurement()) 2139 2140 sysfs_paths = '/sys/class/thermal/thermal_zone*' 2141 paths = glob.glob(sysfs_paths) 2142 for path in paths: 2143 domain_path = os.path.join(path, 'type') 2144 temp_path = os.path.join(path, 'temp') 2145 2146 domain = utils.read_one_line(domain_path) 2147 2148 # Skip when thermal_zone and hwmon have same domain. 2149 if domain in domains: 2150 continue 2151 2152 domain = domain.replace(' ', '_') 2153 new_meas = TempMeasurement(domain, temp_path) 2154 measurements.append(new_meas) 2155 2156 super(TempLogger, self).__init__(measurements, seconds_period, checkpoint_logger) 2157 2158 2159 def save_results(self, resultsdir, fname_prefix=None): 2160 if not fname_prefix: 2161 fname_prefix = 'temp_results_%.0f' % time.time() 2162 super(TempLogger, self).save_results(resultsdir, fname_prefix) 2163 2164 2165 def calc(self, mtype='temp'): 2166 return super(TempLogger, self).calc(mtype) 2167 2168 2169class VideoFpsLogger(MeasurementLogger): 2170 """Class to measure Video FPS.""" 2171 2172 def __init__(self, tab, seconds_period=1.0, checkpoint_logger=None): 2173 """Initialize a VideoFpsLogger. 2174 2175 Args: 2176 tab: Chrome tab object 2177 """ 2178 super(VideoFpsLogger, self).__init__([], seconds_period, 2179 checkpoint_logger) 2180 self._tab = tab 2181 names = self._tab.EvaluateJavaScript( 2182 'Array.from(document.getElementsByTagName("video")).map(v => v.id)') 2183 self.domains = [n or 'video_' + str(i) for i, n in enumerate(names)] 2184 self._last = [0] * len(names) 2185 self.refresh() 2186 2187 def refresh(self): 2188 current = self._tab.EvaluateJavaScript( 2189 'Array.from(document.getElementsByTagName("video")).map(' 2190 'v => v.webkitDecodedFrameCount)') 2191 fps = [(b - a) / self.seconds_period 2192 for a, b in zip(self._last , current)] 2193 self._last = current 2194 return fps 2195 2196 def save_results(self, resultsdir, fname_prefix=None): 2197 if not fname_prefix: 2198 fname_prefix = 'video_fps_results_%.0f' % time.time() 2199 super(VideoFpsLogger, self).save_results(resultsdir, fname_prefix) 2200 2201 def calc(self, mtype='fps'): 2202 return super(VideoFpsLogger, self).calc(mtype) 2203 2204 2205class DiskStateLogger(threading.Thread): 2206 """Records the time percentages the disk stays in its different power modes. 2207 2208 Example code snippet: 2209 mylogger = power_status.DiskStateLogger() 2210 mylogger.start() 2211 result = mylogger.result() 2212 2213 Public methods: 2214 start: Launches the thread and starts measurements. 2215 result: Stops the thread if it's still running and returns measurements. 2216 get_error: Returns the exception in _error if it exists. 2217 2218 Private functions: 2219 _get_disk_state: Returns the disk's current ATA power mode as a string. 2220 2221 Private attributes: 2222 _seconds_period: Disk polling interval in seconds. 2223 _stats: Dict that maps disk states to seconds spent in them. 2224 _running: Flag that is True as long as the logger should keep running. 2225 _time: Timestamp of last disk state reading. 2226 _device_path: The file system path of the disk's device node. 2227 _error: Contains a TestError exception if an unexpected error occured 2228 """ 2229 def __init__(self, seconds_period = 5.0, device_path = None): 2230 """Initializes a logger. 2231 2232 Args: 2233 seconds_period: Disk polling interval in seconds. Default 5.0 2234 device_path: The path of the disk's device node. Default '/dev/sda' 2235 """ 2236 threading.Thread.__init__(self) 2237 self._seconds_period = seconds_period 2238 self._device_path = device_path 2239 self._stats = {} 2240 self._running = False 2241 self._error = None 2242 2243 result = utils.system_output('rootdev -s') 2244 # TODO(tbroch) Won't work for emmc storage and will throw this error in 2245 # keyvals : 'ioctl(SG_IO) error: [Errno 22] Invalid argument' 2246 # Lets implement something complimentary for emmc 2247 if not device_path: 2248 self._device_path = \ 2249 re.sub('(sd[a-z]|mmcblk[0-9]+)p?[0-9]+', '\\1', result) 2250 logging.debug("device_path = %s", self._device_path) 2251 2252 2253 def start(self): 2254 logging.debug("inside DiskStateLogger.start") 2255 if os.path.exists(self._device_path): 2256 logging.debug("DiskStateLogger started") 2257 super(DiskStateLogger, self).start() 2258 2259 2260 def _get_disk_state(self): 2261 """Checks the disk's power mode and returns it as a string. 2262 2263 This uses the SG_IO ioctl to issue a raw SCSI command data block with 2264 the ATA-PASS-THROUGH command that allows SCSI-to-ATA translation (see 2265 T10 document 04-262r8). The ATA command issued is CHECKPOWERMODE1, 2266 which returns the device's current power mode. 2267 """ 2268 2269 def _addressof(obj): 2270 """Shortcut to return the memory address of an object as integer.""" 2271 return ctypes.cast(obj, ctypes.c_void_p).value 2272 2273 scsi_cdb = struct.pack("12B", # SCSI command data block (uint8[12]) 2274 0xa1, # SCSI opcode: ATA-PASS-THROUGH 2275 3 << 1, # protocol: Non-data 2276 1 << 5, # flags: CK_COND 2277 0, # features 2278 0, # sector count 2279 0, 0, 0, # LBA 2280 1 << 6, # flags: ATA-USING-LBA 2281 0xe5, # ATA opcode: CHECKPOWERMODE1 2282 0, # reserved 2283 0, # control (no idea what this is...) 2284 ) 2285 scsi_sense = (ctypes.c_ubyte * 32)() # SCSI sense buffer (uint8[32]) 2286 sgio_header = struct.pack("iiBBHIPPPIIiPBBBBHHiII", # see <scsi/sg.h> 2287 83, # Interface ID magic number (int32) 2288 -1, # data transfer direction: none (int32) 2289 12, # SCSI command data block length (uint8) 2290 32, # SCSI sense data block length (uint8) 2291 0, # iovec_count (not applicable?) (uint16) 2292 0, # data transfer length (uint32) 2293 0, # data block pointer 2294 _addressof(scsi_cdb), # SCSI CDB pointer 2295 _addressof(scsi_sense), # sense buffer pointer 2296 500, # timeout in milliseconds (uint32) 2297 0, # flags (uint32) 2298 0, # pack ID (unused) (int32) 2299 0, # user data pointer (unused) 2300 0, 0, 0, 0, 0, 0, 0, 0, 0, # output params 2301 ) 2302 try: 2303 with open(self._device_path, 'r') as dev: 2304 result = fcntl.ioctl(dev, 0x2285, sgio_header) 2305 except IOError, e: 2306 raise error.TestError('ioctl(SG_IO) error: %s' % str(e)) 2307 _, _, _, _, status, host_status, driver_status = \ 2308 struct.unpack("4x4xxx2x4xPPP4x4x4xPBxxxHH4x4x4x", result) 2309 if status != 0x2: # status: CHECK_CONDITION 2310 raise error.TestError('SG_IO status: %d' % status) 2311 if host_status != 0: 2312 raise error.TestError('SG_IO host status: %d' % host_status) 2313 if driver_status != 0x8: # driver status: SENSE 2314 raise error.TestError('SG_IO driver status: %d' % driver_status) 2315 2316 if scsi_sense[0] != 0x72: # resp. code: current error, descriptor format 2317 raise error.TestError('SENSE response code: %d' % scsi_sense[0]) 2318 if scsi_sense[1] != 0: # sense key: No Sense 2319 raise error.TestError('SENSE key: %d' % scsi_sense[1]) 2320 if scsi_sense[7] < 14: # additional length (ATA status is 14 - 1 bytes) 2321 raise error.TestError('ADD. SENSE too short: %d' % scsi_sense[7]) 2322 if scsi_sense[8] != 0x9: # additional descriptor type: ATA Return Status 2323 raise error.TestError('SENSE descriptor type: %d' % scsi_sense[8]) 2324 if scsi_sense[11] != 0: # errors: none 2325 raise error.TestError('ATA error code: %d' % scsi_sense[11]) 2326 2327 if scsi_sense[13] == 0x00: 2328 return 'standby' 2329 if scsi_sense[13] == 0x80: 2330 return 'idle' 2331 if scsi_sense[13] == 0xff: 2332 return 'active' 2333 return 'unknown(%d)' % scsi_sense[13] 2334 2335 2336 def run(self): 2337 """The Thread's run method.""" 2338 try: 2339 self._time = time.time() 2340 self._running = True 2341 while(self._running): 2342 time.sleep(self._seconds_period) 2343 state = self._get_disk_state() 2344 new_time = time.time() 2345 if state in self._stats: 2346 self._stats[state] += new_time - self._time 2347 else: 2348 self._stats[state] = new_time - self._time 2349 self._time = new_time 2350 except error.TestError, e: 2351 self._error = e 2352 self._running = False 2353 2354 2355 def result(self): 2356 """Stop the logger and return dict with result percentages.""" 2357 if (self._running): 2358 self._running = False 2359 self.join(self._seconds_period * 2) 2360 return AbstractStats.to_percent(self._stats) 2361 2362 2363 def get_error(self): 2364 """Returns the _error exception... please only call after result().""" 2365 return self._error 2366 2367def parse_pmc_s0ix_residency_info(): 2368 """ 2369 Parses S0ix residency for PMC based Intel systems 2370 (skylake/kabylake/apollolake), the debugfs paths might be 2371 different from platform to platform, yet the format is 2372 unified in microseconds. 2373 2374 @returns residency in seconds. 2375 @raises error.TestNAError if the debugfs file not found. 2376 """ 2377 info_path = None 2378 for node in ['/sys/kernel/debug/pmc_core/slp_s0_residency_usec', 2379 '/sys/kernel/debug/telemetry/s0ix_residency_usec']: 2380 if os.path.exists(node): 2381 info_path = node 2382 break 2383 if not info_path: 2384 raise error.TestNAError('S0ix residency file not found') 2385 return float(utils.read_one_line(info_path)) * 1e-6 2386 2387 2388class S0ixResidencyStats(object): 2389 """ 2390 Measures the S0ix residency of a given board over time. 2391 """ 2392 def __init__(self): 2393 self._initial_residency = parse_pmc_s0ix_residency_info() 2394 2395 def get_accumulated_residency_secs(self): 2396 """ 2397 @returns S0ix Residency since the class has been initialized. 2398 """ 2399 return parse_pmc_s0ix_residency_info() - self._initial_residency 2400 2401 2402class DMCFirmwareStats(object): 2403 """ 2404 Collect DMC firmware stats of Intel based system (SKL+), (APL+). 2405 """ 2406 # Intel CPUs only transition to DC6 from DC5. https://git.io/vppcG 2407 DC6_ENTRY_KEY = 'DC5 -> DC6 count' 2408 2409 def __init__(self): 2410 self._initial_stat = DMCFirmwareStats._parse_dmc_info() 2411 2412 def check_fw_loaded(self): 2413 """Check that DMC firmware is loaded 2414 2415 @returns boolean of DMC firmware loaded. 2416 """ 2417 return self._initial_stat['fw loaded'] 2418 2419 def is_dc6_supported(self): 2420 """Check that DMC support DC6 state.""" 2421 return self.DC6_ENTRY_KEY in self._initial_stat 2422 2423 def get_accumulated_dc6_entry(self): 2424 """Check number of DC6 state entry since the class has been initialized. 2425 2426 @returns number of DC6 state entry. 2427 """ 2428 if not self.is_dc6_supported(): 2429 return 0 2430 2431 key = self.DC6_ENTRY_KEY 2432 current_stat = DMCFirmwareStats._parse_dmc_info() 2433 return current_stat[key] - self._initial_stat[key] 2434 2435 @staticmethod 2436 def _parse_dmc_info(): 2437 """ 2438 Parses DMC firmware info for Intel based systems. 2439 2440 @returns dictionary of dmc_fw info 2441 @raises error.TestFail if the debugfs file not found. 2442 """ 2443 path = '/sys/kernel/debug/dri/0/i915_dmc_info' 2444 if not os.path.exists(path): 2445 raise error.TestFail('DMC info file not found.') 2446 2447 with open(path, 'r') as f: 2448 lines = [line.strip() for line in f.readlines()] 2449 2450 # For pre 4.16 kernel. https://git.io/vhThb 2451 if lines[0] == 'not supported': 2452 raise error.TestFail('DMC not supported.') 2453 2454 ret = dict() 2455 for line in lines: 2456 key, val = line.rsplit(': ', 1) 2457 2458 if key == 'fw loaded': 2459 val = val == 'yes' 2460 elif re.match(r'DC\d -> DC\d count', key): 2461 val = int(val) 2462 ret[key] = val 2463 return ret 2464 2465 2466class RC6ResidencyStats(object): 2467 """ 2468 Collect RC6 residency stats of Intel based system. 2469 """ 2470 def __init__(self): 2471 self._rc6_enable_checked = False 2472 self._previous_stat = self._parse_rc6_residency_info() 2473 self._accumulated_stat = 0 2474 2475 # Setup max RC6 residency count for modern chips. The table order 2476 # is in small/big-core first, follows by the uarch name. We don't 2477 # need to deal with the wraparound for devices with v4.17+ kernel 2478 # which has the commit 817cc0791823 ("drm/i915: Handle RC6 counter wrap"). 2479 cpu_uarch = utils.get_intel_cpu_uarch() 2480 self._max_counter = { 2481 # Small-core w/ GEN9 LP graphics 2482 'Airmont': 3579125, 2483 'Goldmont': 3579125, 2484 # Big-core 2485 'Broadwell': 5497558, 2486 'Haswell': 5497558, 2487 'Kaby Lake': 5497558, 2488 'Skylake': 5497558, 2489 }.get(cpu_uarch, None) 2490 2491 def get_accumulated_residency_msecs(self): 2492 """Check number of RC6 state entry since the class has been initialized. 2493 2494 @returns int of RC6 residency in milliseconds since instantiation. 2495 """ 2496 current_stat = self._parse_rc6_residency_info() 2497 2498 # The problem here is that we cannot assume the rc6_residency_ms is 2499 # monotonically increasing by current kernel i915 implementation. 2500 # 2501 # Considering different hardware has different wraparound period, 2502 # this is a mitigation plan to deal with different wraparound period 2503 # on various platforms, in order to make the test platform agnostic. 2504 # 2505 # This scarifes the accuracy of RC6 residency a bit, up on the calling 2506 # period. 2507 # 2508 # Reference: Bug 94852 - [SKL] rc6_residency_ms unreliable 2509 # (https://bugs.freedesktop.org/show_bug.cgi?id=94852) 2510 # 2511 # However for modern processors with a known overflow count, apply 2512 # constant of RC6 max counter to improve accuracy. 2513 # 2514 # Note that the max counter is bound for sysfs overflow, while the 2515 # accumulated residency here is the diff against the first reading. 2516 if current_stat < self._previous_stat: 2517 if self._max_counter is None: 2518 logging.warning('GPU: Detect rc6_residency_ms wraparound') 2519 self._accumulated_stat += current_stat 2520 else: 2521 self._accumulated_stat += current_stat + (self._max_counter - self._previous_stat) 2522 else: 2523 self._accumulated_stat += current_stat - self._previous_stat 2524 2525 self._previous_stat = current_stat 2526 return self._accumulated_stat 2527 2528 def _is_rc6_enable(self): 2529 """ 2530 Verified that RC6 is enable. 2531 2532 @returns Boolean of RC6 enable status. 2533 @raises error.TestFail if the sysfs file not found. 2534 """ 2535 path = '/sys/class/drm/card0/power/rc6_enable' 2536 if not os.path.exists(path): 2537 raise error.TestFail('RC6 enable file not found.') 2538 2539 return (int(utils.read_one_line(path)) & 0x1) == 0x1 2540 2541 def _parse_rc6_residency_info(self): 2542 """ 2543 Parses RC6 residency info for Intel based systems. 2544 2545 @returns int of RC6 residency in millisec since boot. 2546 @raises error.TestFail if the sysfs file not found or RC6 not enabled. 2547 """ 2548 if not self._rc6_enable_checked: 2549 if not self._is_rc6_enable(): 2550 raise error.TestFail('RC6 is not enabled.') 2551 self._rc6_enable_checked = True 2552 2553 path = '/sys/class/drm/card0/power/rc6_residency_ms' 2554 if not os.path.exists(path): 2555 raise error.TestFail('RC6 residency file not found.') 2556 2557 return int(utils.read_one_line(path)) 2558 2559 2560class PCHPowergatingStats(object): 2561 """ 2562 Collect PCH powergating status of intel based system. 2563 """ 2564 PMC_CORE_PATH = '/sys/kernel/debug/pmc_core/pch_ip_power_gating_status' 2565 TELEMETRY_PATH = '/sys/kernel/debug/telemetry/soc_states' 2566 2567 def __init__(self): 2568 self._stat = {} 2569 2570 def check_s0ix_requirement(self): 2571 """ 2572 Check PCH powergating status with S0ix requirement. 2573 2574 @returns list of PCH IP block name that need to be powergated for low 2575 power consumption S0ix, empty list if none. 2576 """ 2577 # PCH IP block that is on for S0ix. Ignore these IP block. 2578 S0IX_WHITELIST = set([ 2579 'PMC', 'OPI-DMI', 'SPI / eSPI', 'XHCI', 'xHCI', 'FUSE', 'Fuse', 2580 'PCIE0', 'NPKVRC', 'NPKVNN', 'NPK_VNN', 'PSF1', 'PSF2', 'PSF3', 2581 'PSF4', 'SBR0', 'SBR1', 'SBR2', 'SBR4', 'SBR5', 'SBR6', 'SBR7']) 2582 2583 # PCH IP block that is on/off for S0ix depend on features enabled. 2584 # Add log when these IPs state are on. 2585 S0IX_WARNLIST = set([ 2586 'HDA-PGD0', 'HDA-PGD1', 'HDA-PGD2', 'HDA-PGD3', 'LPSS', 2587 'AVSPGD1', 'AVSPGD4']) 2588 2589 # CNV device has 0x31dc as devid . 2590 if len(utils.system_output('lspci -d :31dc')) > 0: 2591 S0IX_WHITELIST.add('CNV') 2592 2593 # HrP2 device has 0x02f0 as devid. 2594 if len(utils.system_output('lspci -d :02f0')) > 0: 2595 S0IX_WHITELIST.update(['CNVI', 'NPK_AON']) 2596 2597 on_ip = set(ip['name'] for ip in self._stat if ip['state']) 2598 on_ip -= S0IX_WHITELIST 2599 2600 if on_ip: 2601 on_ip_in_warn_list = on_ip & S0IX_WARNLIST 2602 if on_ip_in_warn_list: 2603 logging.warn('Found PCH IP that may be able to powergate: %s', 2604 ', '.join(on_ip_in_warn_list)) 2605 on_ip -= S0IX_WARNLIST 2606 2607 if on_ip: 2608 logging.error('Found PCH IP that need to powergate: %s', 2609 ', '.join(on_ip)) 2610 return False 2611 return True 2612 2613 def read_pch_powergating_info(self, sleep_seconds=1): 2614 """ 2615 Read PCH powergating status info for Intel based systems. 2616 2617 Intel currently shows powergating status in 2 different place in debugfs 2618 depend on which CPU platform. 2619 2620 @param sleep_seconds: sleep time to make DUT idle before read the data. 2621 2622 @raises error.TestFail if the debugfs file not found or parsing error. 2623 """ 2624 if os.path.exists(self.PMC_CORE_PATH): 2625 logging.info('Use PCH powergating info at %s', self.PMC_CORE_PATH) 2626 time.sleep(sleep_seconds) 2627 self._read_pcm_core_powergating_info() 2628 return 2629 2630 if os.path.exists(self.TELEMETRY_PATH): 2631 logging.info('Use PCH powergating info at %s', self.TELEMETRY_PATH) 2632 time.sleep(sleep_seconds) 2633 self._read_telemetry_powergating_info() 2634 return 2635 2636 raise error.TestFail('PCH powergating info file not found.') 2637 2638 def _read_pcm_core_powergating_info(self): 2639 """ 2640 read_pch_powergating_info() for Intel Core KBL+ 2641 2642 @raises error.TestFail if parsing error. 2643 """ 2644 with open(self.PMC_CORE_PATH, 'r') as f: 2645 lines = [line.strip() for line in f.readlines()] 2646 2647 # Example pattern to match: 2648 # PCH IP: 0 - PMC State: On 2649 # PCH IP: 1 - SATA State: Off 2650 pattern = r'PCH IP:\s+(?P<id>\d+)\s+' \ 2651 r'- (?P<name>.*\w)\s+' \ 2652 r'State: (?P<state>Off|On)' 2653 matcher = re.compile(pattern) 2654 ret = [] 2655 for i, line in enumerate(lines): 2656 match = matcher.match(line) 2657 if not match: 2658 raise error.TestFail('Can not parse PCH powergating info: ', 2659 line) 2660 2661 index = int(match.group('id')) 2662 if i != index: 2663 raise error.TestFail('Wrong index for PCH powergating info: ', 2664 line) 2665 2666 name = match.group('name') 2667 state = match.group('state') == 'On' 2668 2669 ret.append({'name': name, 'state': state}) 2670 self._stat = ret 2671 2672 def _read_telemetry_powergating_info(self): 2673 """ 2674 read_pch_powergating_info() for Intel Atom APL+ 2675 2676 @raises error.TestFail if parsing error. 2677 """ 2678 with open(self.TELEMETRY_PATH, 'r') as f: 2679 raw_str = f.read() 2680 2681 # Example pattern to match: 2682 # -------------------------------------- 2683 # South Complex PowerGate Status 2684 # -------------------------------------- 2685 # Device PG 2686 # LPSS 1 2687 # SPI 1 2688 # FUSE 0 2689 # 2690 # --------------------------------------- 2691 trimed_pattern = r'.*South Complex PowerGate Status\n' \ 2692 r'-+\n' \ 2693 r'Device\s+PG\n' \ 2694 r'(?P<trimmed_section>(\w+\s+[0|1]\n)+)' \ 2695 r'\n-+\n.*' 2696 trimed_match = re.match(trimed_pattern, raw_str, re.DOTALL) 2697 if not trimed_match: 2698 raise error.TestFail('Can not parse PCH powergating info: ', 2699 raw_str) 2700 trimmed_str = trimed_match.group('trimmed_section').strip() 2701 lines = [line.strip() for line in trimmed_str.split('\n')] 2702 2703 matcher = re.compile(r'(?P<name>\w+)\s+(?P<state>[0|1])') 2704 ret = [] 2705 for line in lines: 2706 match = matcher.match(line) 2707 if not match: 2708 raise error.TestFail('Can not parse PCH powergating info: %s', 2709 line) 2710 2711 name = match.group('name') 2712 state = match.group('state') == '0' # 0 means on and 1 means off 2713 2714 ret.append({'name': name, 'state': state}) 2715 self._stat = ret 2716 2717def has_rc6_support(): 2718 """ 2719 Helper to examine that RC6 is enabled with residency counter. 2720 2721 @returns Boolean of RC6 support status. 2722 """ 2723 enable_path = '/sys/class/drm/card0/power/rc6_enable' 2724 residency_path = '/sys/class/drm/card0/power/rc6_residency_ms' 2725 2726 has_rc6_enabled = os.path.exists(enable_path) 2727 has_rc6_residency = False 2728 rc6_enable_mask = 0 2729 2730 if has_rc6_enabled: 2731 # TODO (harry.pan): Some old chip has RC6P and RC6PP 2732 # in the bits[1:2]; in case of that, ideally these time 2733 # slice will fall into RC0, fix it up if required. 2734 rc6_enable_mask = int(utils.read_one_line(enable_path)) 2735 has_rc6_enabled &= (rc6_enable_mask) & 0x1 == 0x1 2736 has_rc6_residency = os.path.exists(residency_path) 2737 2738 logging.debug("GPU: RC6 residency support: %s, mask: 0x%x", 2739 {True: "yes", False: "no"} [has_rc6_enabled and has_rc6_residency], 2740 rc6_enable_mask) 2741 2742 return (has_rc6_enabled and has_rc6_residency) 2743 2744class GPURC6Stats(AbstractStats): 2745 """ 2746 GPU RC6 statistics to give ratio of RC6 and RC0 residency 2747 2748 Protected Attributes: 2749 _rc6: object of RC6ResidencyStats 2750 """ 2751 def __init__(self): 2752 self._rc6 = RC6ResidencyStats() 2753 super(GPURC6Stats, self).__init__(name='gpuidle') 2754 2755 def _read_stats(self): 2756 total = int(time.time() * 1000) 2757 msecs = self._rc6.get_accumulated_residency_msecs() 2758 stats = collections.defaultdict(int) 2759 stats['RC6'] += msecs 2760 stats['RC0'] += total - msecs 2761 logging.debug("GPU: RC6 residency: %d ms", msecs) 2762 return stats 2763