diff --git a/devlib/__init__.py b/devlib/__init__.py index 51a8e47..911c50d 100644 --- a/devlib/__init__.py +++ b/devlib/__init__.py @@ -13,6 +13,7 @@ from devlib.instrument import Instrument, InstrumentChannel, Measurement, Measur from devlib.instrument import MEASUREMENT_TYPES, INSTANTANEOUS, CONTINUOUS from devlib.instrument.daq import DaqInstrument from devlib.instrument.energy_probe import EnergyProbeInstrument +from devlib.instrument.frames import GfxInfoFramesInstrument from devlib.instrument.hwmon import HwmonInstrument from devlib.instrument.monsoon import MonsoonInstrument from devlib.instrument.netstats import NetstatsInstrument diff --git a/devlib/exception.py b/devlib/exception.py index 16dd04f..11b19e0 100644 --- a/devlib/exception.py +++ b/devlib/exception.py @@ -13,7 +13,6 @@ # limitations under the License. # - class DevlibError(Exception): """Base class for all Devlib exceptions.""" pass @@ -49,3 +48,42 @@ class TimeoutError(DevlibError): def __str__(self): return '\n'.join([self.message, 'OUTPUT:', self.output or '']) + + +class WorkerThreadError(DevlibError): + """ + This should get raised in the main thread if a non-WAError-derived + exception occurs on a worker/background thread. If a WAError-derived + exception is raised in the worker, then it that exception should be + re-raised on the main thread directly -- the main point of this is to + preserve the backtrace in the output, and backtrace doesn't get output for + WAErrors. + + """ + + def __init__(self, thread, exc_info): + self.thread = thread + self.exc_info = exc_info + orig = self.exc_info[1] + orig_name = type(orig).__name__ + message = 'Exception of type {} occured on thread {}:\n'.format(orig_name, thread) + message += '{}\n{}: {}'.format(get_traceback(self.exc_info), orig_name, orig) + super(WorkerThreadError, self).__init__(message) + + +def get_traceback(exc=None): + """ + Returns the string with the traceback for the specifiec exc + object, or for the current exception exc is not specified. + + """ + import StringIO, traceback, sys + if exc is None: + exc = sys.exc_info() + if not exc: + return None + tb = exc[2] + sio = StringIO.StringIO() + traceback.print_tb(tb, file=sio) + del tb # needs to be done explicitly see: http://docs.python.org/2/library/sys.html#sys.exc_info + return sio.getvalue() diff --git a/devlib/instrument/__init__.py b/devlib/instrument/__init__.py index 9d898c4..044c7d4 100644 --- a/devlib/instrument/__init__.py +++ b/devlib/instrument/__init__.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. # +from __future__ import division import csv import logging import collections @@ -24,28 +25,33 @@ from devlib.utils.types import numeric INSTANTANEOUS = 1 CONTINUOUS = 2 +MEASUREMENT_TYPES = {} # populated further down -class MeasurementType(tuple): - __slots__ = [] +class MeasurementType(object): - def __new__(cls, name, units, category=None): - return tuple.__new__(cls, (name, units, category)) + def __init__(self, name, units, category=None, conversions=None): + self.name = name + self.units = units + self.category = category + self.conversions = {} + if conversions is not None: + for key, value in conversions.iteritems(): + if not callable(value): + msg = 'Converter must be callable; got {} "{}"' + raise ValueError(msg.format(type(value), value)) + self.conversions[key] = value - @property - def name(self): - return tuple.__getitem__(self, 0) - - @property - def units(self): - return tuple.__getitem__(self, 1) - - @property - def category(self): - return tuple.__getitem__(self, 2) - - def __getitem__(self, item): - raise TypeError() + def convert(self, value, to): + if isinstance(to, basestring) and to in MEASUREMENT_TYPES: + to = MEASUREMENT_TYPES[to] + if not isinstance(to, MeasurementType): + msg = 'Unexpected conversion target: "{}"' + raise ValueError(msg.format(to)) + if not to.name in self.conversions: + msg = 'No conversion from {} to {} available' + raise ValueError(msg.format(self.name, to.name)) + return self.conversions[to.name](value) def __cmp__(self, other): if isinstance(other, MeasurementType): @@ -55,12 +61,28 @@ class MeasurementType(tuple): def __str__(self): return self.name - __repr__ = __str__ + def __repr__(self): + if self.category: + text = 'MeasurementType({}, {}, {})' + return text.format(self.name, self.units, self.category) + else: + text = 'MeasurementType({}, {})' + return text.format(self.name, self.units) # Standard measures _measurement_types = [ - MeasurementType('time', 'seconds'), + MeasurementType('unknown', None), + MeasurementType('time', 'seconds', + conversions={ + 'time_us': lambda x: x * 1000, + } + ), + MeasurementType('time_us', 'microseconds', + conversions={ + 'time': lambda x: x / 1000, + } + ), MeasurementType('temperature', 'degrees'), MeasurementType('power', 'watts', 'power/energy'), @@ -71,8 +93,11 @@ _measurement_types = [ MeasurementType('tx', 'bytes', 'data transfer'), MeasurementType('rx', 'bytes', 'data transfer'), MeasurementType('tx/rx', 'bytes', 'data transfer'), + + MeasurementType('frames', 'frames', 'ui render'), ] -MEASUREMENT_TYPES = {m.name: m for m in _measurement_types} +for m in _measurement_types: + MEASUREMENT_TYPES[m.name] = m class Measurement(object): @@ -108,10 +133,12 @@ class Measurement(object): class MeasurementsCsv(object): - def __init__(self, path, channels): + def __init__(self, path, channels=None): self.path = path self.channels = channels self._fh = open(path, 'rb') + if self.channels is None: + self._load_channels() def measurements(self): return list(self.itermeasurements()) @@ -124,6 +151,29 @@ class MeasurementsCsv(object): values = map(numeric, row) yield [Measurement(v, c) for (v, c) in zip(values, self.channels)] + def _load_channels(self): + self._fh.seek(0) + reader = csv.reader(self._fh) + header = reader.next() + self._fh.seek(0) + + self.channels = [] + for entry in header: + for mt in MEASUREMENT_TYPES: + suffix = '_{}'.format(mt) + if entry.endswith(suffix): + site = entry[:-len(suffix)] + measure = mt + name = '{}_{}'.format(site, measure) + break + else: + site = entry + measure = 'unknown' + name = entry + + chan = InstrumentChannel(name, site, measure) + self.channels.append(chan) + class InstrumentChannel(object): diff --git a/devlib/instrument/frames.py b/devlib/instrument/frames.py new file mode 100644 index 0000000..d5a2147 --- /dev/null +++ b/devlib/instrument/frames.py @@ -0,0 +1,76 @@ +from devlib.instrument import (Instrument, CONTINUOUS, + MeasurementsCsv, MeasurementType) +from devlib.utils.rendering import (GfxinfoFrameCollector, + SurfaceFlingerFrameCollector, + SurfaceFlingerFrame, + read_gfxinfo_columns) + + +class FramesInstrument(Instrument): + + mode = CONTINUOUS + collector_cls = None + + def __init__(self, target, collector_target, period=2, keep_raw=True): + super(FramesInstrument, self).__init__(target) + self.collector_target = collector_target + self.period = period + self.keep_raw = keep_raw + self.collector = None + self.header = None + self._need_reset = True + self._init_channels() + + def reset(self, sites=None, kinds=None, channels=None): + super(FramesInstrument, self).reset(sites, kinds, channels) + self.collector = self.collector_cls(self.target, self.period, + self.collector_target, self.header) + self._need_reset = False + + def start(self): + if self._need_reset: + self.reset() + self.collector.start() + + def stop(self): + self.collector.stop() + self._need_reset = True + + def get_data(self, outfile): + raw_outfile = None + if self.keep_raw: + raw_outfile = outfile + '.raw' + self.collector.process_frames(raw_outfile) + active_sites = [chan.label for chan in self.active_channels] + self.collector.write_frames(outfile, columns=active_sites) + return MeasurementsCsv(outfile, self.active_channels) + + def _init_channels(self): + raise NotImplementedError() + + +class GfxInfoFramesInstrument(FramesInstrument): + + mode = CONTINUOUS + collector_cls = GfxinfoFrameCollector + + def _init_channels(self): + columns = read_gfxinfo_columns(self.target) + for entry in columns: + if entry == 'Flags': + self.add_channel('Flags', MeasurementType('flags', 'flags')) + else: + self.add_channel(entry, 'time_us') + self.header = [chan.label for chan in self.channels.values()] + + +class SurfaceFlingerFramesInstrument(FramesInstrument): + + mode = CONTINUOUS + collector_cls = SurfaceFlingerFrameCollector + + def _init_channels(self): + for field in SurfaceFlingerFrame._fields: + # remove the "_time" from filed names to avoid duplication + self.add_channel(field[:-5], 'time_us') + self.header = [chan.label for chan in self.channels.values()] diff --git a/devlib/utils/rendering.py b/devlib/utils/rendering.py new file mode 100644 index 0000000..3b7b6c4 --- /dev/null +++ b/devlib/utils/rendering.py @@ -0,0 +1,205 @@ +import csv +import logging +import os +import re +import shutil +import sys +import tempfile +import threading +import time +from collections import namedtuple, OrderedDict +from distutils.version import LooseVersion + +from devlib.exception import WorkerThreadError, TargetNotRespondingError, TimeoutError + + +logger = logging.getLogger('rendering') + +SurfaceFlingerFrame = namedtuple('SurfaceFlingerFrame', + 'desired_present_time actual_present_time frame_ready_time') + + +class FrameCollector(threading.Thread): + + def __init__(self, target, period): + super(FrameCollector, self).__init__() + self.target = target + self.period = period + self.stop_signal = threading.Event() + self.frames = [] + + self.temp_file = None + self.refresh_period = None + self.drop_threshold = None + self.unresponsive_count = 0 + self.last_ready_time = None + self.exc = None + self.header = None + + def run(self): + logger.debug('Surface flinger frame data collection started.') + try: + self.stop_signal.clear() + fd, self.temp_file = tempfile.mkstemp() + logger.debug('temp file: {}'.format(self.temp_file)) + wfh = os.fdopen(fd, 'wb') + try: + while not self.stop_signal.is_set(): + self.collect_frames(wfh) + time.sleep(self.period) + finally: + wfh.close() + except (TargetNotRespondingError, TimeoutError): # pylint: disable=W0703 + raise + except Exception, e: # pylint: disable=W0703 + logger.warning('Exception on collector thread: {}({})'.format(e.__class__.__name__, e)) + self.exc = WorkerThreadError(self.name, sys.exc_info()) + logger.debug('Surface flinger frame data collection stopped.') + + def stop(self): + self.stop_signal.set() + self.join() + if self.unresponsive_count: + message = 'FrameCollector was unrepsonsive {} times.'.format(self.unresponsive_count) + if self.unresponsive_count > 10: + logger.warning(message) + else: + logger.debug(message) + if self.exc: + raise self.exc # pylint: disable=E0702 + + def process_frames(self, outfile=None): + if not self.temp_file: + raise RuntimeError('Attempting to process frames before running the collector') + with open(self.temp_file) as fh: + self._process_raw_file(fh) + if outfile: + shutil.copy(self.temp_file, outfile) + os.unlink(self.temp_file) + self.temp_file = None + + def write_frames(self, outfile, columns=None): + if columns is None: + header = self.header + frames = self.frames + else: + header = [c for c in self.header if c in columns] + indexes = [self.header.index(c) for c in header] + frames = [[f[i] for i in indexes] for f in self.frames] + with open(outfile, 'w') as wfh: + writer = csv.writer(wfh) + if header: + writer.writerow(header) + writer.writerows(frames) + + def collect_frames(self, wfh): + raise NotImplementedError() + + def clear(self): + raise NotImplementedError() + + def _process_raw_file(self, fh): + raise NotImplementedError() + + +class SurfaceFlingerFrameCollector(FrameCollector): + + def __init__(self, target, period, view, header=None): + super(SurfaceFlingerFrameCollector, self).__init__(target, period) + self.view = view + self.header = header or SurfaceFlingerFrame._fields + + def collect_frames(self, wfh): + for activity in self.list(): + if activity == self.view: + wfh.write(self.get_latencies(activity)) + + def clear(self): + self.target.execute('dumpsys SurfaceFlinger --latency-clear ') + + def get_latencies(self, activity): + cmd = 'dumpsys SurfaceFlinger --latency "{}"' + return self.target.execute(cmd.format(activity)) + + def list(self): + return self.target.execute('dumpsys SurfaceFlinger --list').split('\r\n') + + def _process_raw_file(self, fh): + text = fh.read().replace('\r\n', '\n').replace('\r', '\n') + for line in text.split('\n'): + line = line.strip() + if line: + self._process_trace_line(line) + + def _process_trace_line(self, line): + parts = line.split() + if len(parts) == 3: + frame = SurfaceFlingerFrame(*map(int, parts)) + if not frame.frame_ready_time: + return # "null" frame + if frame.frame_ready_time <= self.last_ready_time: + return # duplicate frame + if (frame.frame_ready_time - frame.desired_present_time) > self.drop_threshold: + logger.debug('Dropping bogus frame {}.'.format(line)) + return # bogus data + self.last_ready_time = frame.frame_ready_time + self.frames.append(frame) + elif len(parts) == 1: + self.refresh_period = int(parts[0]) + self.drop_threshold = self.refresh_period * 1000 + elif 'SurfaceFlinger appears to be unresponsive, dumping anyways' in line: + self.unresponsive_count += 1 + else: + logger.warning('Unexpected SurfaceFlinger dump output: {}'.format(line)) + + +def read_gfxinfo_columns(target): + output = target.execute('dumpsys gfxinfo --list framestats') + lines = iter(output.split('\n')) + for line in lines: + if line.startswith('---PROFILEDATA---'): + break + columns_line = lines.next() + return columns_line.split(',')[:-1] # has a trailing ',' + + +class GfxinfoFrameCollector(FrameCollector): + + def __init__(self, target, period, package, header=None): + super(GfxinfoFrameCollector, self).__init__(target, period) + self.package = package + self.header = None + self._init_header(header) + + def collect_frames(self, wfh): + cmd = 'dumpsys gfxinfo {} framestats' + wfh.write(self.target.execute(cmd.format(self.package))) + + def clear(self): + pass + + def _init_header(self, header): + if header is not None: + self.header = header + else: + self.header = read_gfxinfo_columns(self.target) + + def _process_raw_file(self, fh): + found = False + try: + while True: + for line in fh: + if line.startswith('---PROFILEDATA---'): + found = True + break + + fh.next() # headers + for line in fh: + if line.startswith('---PROFILEDATA---'): + break + self.frames.append(map(int, line.strip().split(',')[:-1])) # has a trailing ',' + except StopIteration: + pass + if not found: + logger.warning('Could not find frames data in gfxinfo output') + return