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