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