Home | History | Annotate | Download | only in power
      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