Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 1 | import csv |
| 2 | import logging |
| 3 | import os |
| 4 | import re |
| 5 | import shutil |
| 6 | import sys |
| 7 | import tempfile |
| 8 | import threading |
| 9 | import time |
| 10 | from collections import namedtuple, OrderedDict |
| 11 | from distutils.version import LooseVersion |
| 12 | |
| 13 | from devlib.exception import WorkerThreadError, TargetNotRespondingError, TimeoutError |
| 14 | |
| 15 | |
| 16 | logger = logging.getLogger('rendering') |
| 17 | |
Sergei Trofimov | 2b3cee6 | 2017-06-06 14:47:42 +0100 | [diff] [blame] | 18 | SurfaceFlingerFrame = namedtuple('SurfaceFlingerFrame', |
| 19 | 'desired_present_time actual_present_time frame_ready_time') |
| 20 | |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 21 | |
| 22 | class FrameCollector(threading.Thread): |
| 23 | |
| 24 | def __init__(self, target, period): |
| 25 | super(FrameCollector, self).__init__() |
| 26 | self.target = target |
| 27 | self.period = period |
| 28 | self.stop_signal = threading.Event() |
| 29 | self.frames = [] |
| 30 | |
| 31 | self.temp_file = None |
| 32 | self.refresh_period = None |
| 33 | self.drop_threshold = None |
| 34 | self.unresponsive_count = 0 |
| 35 | self.last_ready_time = None |
| 36 | self.exc = None |
| 37 | self.header = None |
| 38 | |
| 39 | def run(self): |
| 40 | logger.debug('Surface flinger frame data collection started.') |
| 41 | try: |
| 42 | self.stop_signal.clear() |
| 43 | fd, self.temp_file = tempfile.mkstemp() |
| 44 | logger.debug('temp file: {}'.format(self.temp_file)) |
| 45 | wfh = os.fdopen(fd, 'wb') |
| 46 | try: |
| 47 | while not self.stop_signal.is_set(): |
| 48 | self.collect_frames(wfh) |
| 49 | time.sleep(self.period) |
| 50 | finally: |
| 51 | wfh.close() |
| 52 | except (TargetNotRespondingError, TimeoutError): # pylint: disable=W0703 |
| 53 | raise |
| 54 | except Exception, e: # pylint: disable=W0703 |
| 55 | logger.warning('Exception on collector thread: {}({})'.format(e.__class__.__name__, e)) |
| 56 | self.exc = WorkerThreadError(self.name, sys.exc_info()) |
| 57 | logger.debug('Surface flinger frame data collection stopped.') |
| 58 | |
| 59 | def stop(self): |
| 60 | self.stop_signal.set() |
| 61 | self.join() |
| 62 | if self.unresponsive_count: |
| 63 | message = 'FrameCollector was unrepsonsive {} times.'.format(self.unresponsive_count) |
| 64 | if self.unresponsive_count > 10: |
| 65 | logger.warning(message) |
| 66 | else: |
| 67 | logger.debug(message) |
| 68 | if self.exc: |
| 69 | raise self.exc # pylint: disable=E0702 |
| 70 | |
| 71 | def process_frames(self, outfile=None): |
| 72 | if not self.temp_file: |
| 73 | raise RuntimeError('Attempting to process frames before running the collector') |
| 74 | with open(self.temp_file) as fh: |
| 75 | self._process_raw_file(fh) |
| 76 | if outfile: |
| 77 | shutil.copy(self.temp_file, outfile) |
| 78 | os.unlink(self.temp_file) |
| 79 | self.temp_file = None |
| 80 | |
| 81 | def write_frames(self, outfile, columns=None): |
| 82 | if columns is None: |
| 83 | header = self.header |
| 84 | frames = self.frames |
| 85 | else: |
| 86 | header = [c for c in self.header if c in columns] |
| 87 | indexes = [self.header.index(c) for c in header] |
| 88 | frames = [[f[i] for i in indexes] for f in self.frames] |
| 89 | with open(outfile, 'w') as wfh: |
| 90 | writer = csv.writer(wfh) |
| 91 | if header: |
| 92 | writer.writerow(header) |
| 93 | writer.writerows(frames) |
| 94 | |
| 95 | def collect_frames(self, wfh): |
| 96 | raise NotImplementedError() |
| 97 | |
| 98 | def clear(self): |
| 99 | raise NotImplementedError() |
| 100 | |
| 101 | def _process_raw_file(self, fh): |
| 102 | raise NotImplementedError() |
| 103 | |
| 104 | |
Sergei Trofimov | 2b3cee6 | 2017-06-06 14:47:42 +0100 | [diff] [blame] | 105 | class SurfaceFlingerFrameCollector(FrameCollector): |
| 106 | |
| 107 | def __init__(self, target, period, view, header=None): |
| 108 | super(SurfaceFlingerFrameCollector, self).__init__(target, period) |
| 109 | self.view = view |
| 110 | self.header = header or SurfaceFlingerFrame._fields |
| 111 | |
| 112 | def collect_frames(self, wfh): |
| 113 | for activity in self.list(): |
| 114 | if activity == self.view: |
| 115 | wfh.write(self.get_latencies(activity)) |
| 116 | |
| 117 | def clear(self): |
| 118 | self.target.execute('dumpsys SurfaceFlinger --latency-clear ') |
| 119 | |
| 120 | def get_latencies(self, activity): |
| 121 | cmd = 'dumpsys SurfaceFlinger --latency "{}"' |
| 122 | return self.target.execute(cmd.format(activity)) |
| 123 | |
| 124 | def list(self): |
| 125 | return self.target.execute('dumpsys SurfaceFlinger --list').split('\r\n') |
| 126 | |
| 127 | def _process_raw_file(self, fh): |
| 128 | text = fh.read().replace('\r\n', '\n').replace('\r', '\n') |
| 129 | for line in text.split('\n'): |
| 130 | line = line.strip() |
| 131 | if line: |
| 132 | self._process_trace_line(line) |
| 133 | |
| 134 | def _process_trace_line(self, line): |
| 135 | parts = line.split() |
| 136 | if len(parts) == 3: |
| 137 | frame = SurfaceFlingerFrame(*map(int, parts)) |
| 138 | if not frame.frame_ready_time: |
| 139 | return # "null" frame |
| 140 | if frame.frame_ready_time <= self.last_ready_time: |
| 141 | return # duplicate frame |
| 142 | if (frame.frame_ready_time - frame.desired_present_time) > self.drop_threshold: |
| 143 | logger.debug('Dropping bogus frame {}.'.format(line)) |
| 144 | return # bogus data |
| 145 | self.last_ready_time = frame.frame_ready_time |
| 146 | self.frames.append(frame) |
| 147 | elif len(parts) == 1: |
| 148 | self.refresh_period = int(parts[0]) |
| 149 | self.drop_threshold = self.refresh_period * 1000 |
| 150 | elif 'SurfaceFlinger appears to be unresponsive, dumping anyways' in line: |
| 151 | self.unresponsive_count += 1 |
| 152 | else: |
| 153 | logger.warning('Unexpected SurfaceFlinger dump output: {}'.format(line)) |
| 154 | |
| 155 | |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 156 | def read_gfxinfo_columns(target): |
| 157 | output = target.execute('dumpsys gfxinfo --list framestats') |
| 158 | lines = iter(output.split('\n')) |
| 159 | for line in lines: |
| 160 | if line.startswith('---PROFILEDATA---'): |
| 161 | break |
| 162 | columns_line = lines.next() |
| 163 | return columns_line.split(',')[:-1] # has a trailing ',' |
| 164 | |
| 165 | |
| 166 | class GfxinfoFrameCollector(FrameCollector): |
| 167 | |
| 168 | def __init__(self, target, period, package, header=None): |
| 169 | super(GfxinfoFrameCollector, self).__init__(target, period) |
| 170 | self.package = package |
| 171 | self.header = None |
| 172 | self._init_header(header) |
| 173 | |
| 174 | def collect_frames(self, wfh): |
| 175 | cmd = 'dumpsys gfxinfo {} framestats' |
| 176 | wfh.write(self.target.execute(cmd.format(self.package))) |
| 177 | |
| 178 | def clear(self): |
| 179 | pass |
| 180 | |
| 181 | def _init_header(self, header): |
| 182 | if header is not None: |
| 183 | self.header = header |
| 184 | else: |
| 185 | self.header = read_gfxinfo_columns(self.target) |
| 186 | |
| 187 | def _process_raw_file(self, fh): |
| 188 | found = False |
| 189 | try: |
| 190 | while True: |
| 191 | for line in fh: |
| 192 | if line.startswith('---PROFILEDATA---'): |
| 193 | found = True |
| 194 | break |
| 195 | |
| 196 | fh.next() # headers |
| 197 | for line in fh: |
| 198 | if line.startswith('---PROFILEDATA---'): |
| 199 | break |
| 200 | self.frames.append(map(int, line.strip().split(',')[:-1])) # has a trailing ',' |
| 201 | except StopIteration: |
| 202 | pass |
| 203 | if not found: |
| 204 | logger.warning('Could not find frames data in gfxinfo output') |
| 205 | return |