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 | f692315 | 2017-09-07 17:36:18 +0100 | [diff] [blame] | 21 | VSYNC_INTERVAL = 16666667 |
| 22 | |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 23 | |
| 24 | class FrameCollector(threading.Thread): |
| 25 | |
| 26 | def __init__(self, target, period): |
| 27 | super(FrameCollector, self).__init__() |
| 28 | self.target = target |
| 29 | self.period = period |
| 30 | self.stop_signal = threading.Event() |
| 31 | self.frames = [] |
| 32 | |
| 33 | self.temp_file = None |
| 34 | self.refresh_period = None |
| 35 | self.drop_threshold = None |
| 36 | self.unresponsive_count = 0 |
| 37 | self.last_ready_time = None |
| 38 | self.exc = None |
| 39 | self.header = None |
| 40 | |
| 41 | def run(self): |
| 42 | logger.debug('Surface flinger frame data collection started.') |
| 43 | try: |
| 44 | self.stop_signal.clear() |
| 45 | fd, self.temp_file = tempfile.mkstemp() |
| 46 | logger.debug('temp file: {}'.format(self.temp_file)) |
| 47 | wfh = os.fdopen(fd, 'wb') |
| 48 | try: |
| 49 | while not self.stop_signal.is_set(): |
| 50 | self.collect_frames(wfh) |
| 51 | time.sleep(self.period) |
| 52 | finally: |
| 53 | wfh.close() |
| 54 | except (TargetNotRespondingError, TimeoutError): # pylint: disable=W0703 |
| 55 | raise |
| 56 | except Exception, e: # pylint: disable=W0703 |
| 57 | logger.warning('Exception on collector thread: {}({})'.format(e.__class__.__name__, e)) |
| 58 | self.exc = WorkerThreadError(self.name, sys.exc_info()) |
| 59 | logger.debug('Surface flinger frame data collection stopped.') |
| 60 | |
| 61 | def stop(self): |
| 62 | self.stop_signal.set() |
| 63 | self.join() |
| 64 | if self.unresponsive_count: |
| 65 | message = 'FrameCollector was unrepsonsive {} times.'.format(self.unresponsive_count) |
| 66 | if self.unresponsive_count > 10: |
| 67 | logger.warning(message) |
| 68 | else: |
| 69 | logger.debug(message) |
| 70 | if self.exc: |
| 71 | raise self.exc # pylint: disable=E0702 |
| 72 | |
| 73 | def process_frames(self, outfile=None): |
| 74 | if not self.temp_file: |
| 75 | raise RuntimeError('Attempting to process frames before running the collector') |
| 76 | with open(self.temp_file) as fh: |
| 77 | self._process_raw_file(fh) |
| 78 | if outfile: |
| 79 | shutil.copy(self.temp_file, outfile) |
| 80 | os.unlink(self.temp_file) |
| 81 | self.temp_file = None |
| 82 | |
| 83 | def write_frames(self, outfile, columns=None): |
| 84 | if columns is None: |
| 85 | header = self.header |
| 86 | frames = self.frames |
| 87 | else: |
Sergei Trofimov | d952abf | 2017-09-19 13:48:08 +0100 | [diff] [blame] | 88 | indexes = [] |
| 89 | for c in columns: |
| 90 | if c not in self.header: |
| 91 | msg = 'Invalid column "{}"; must be in {}' |
| 92 | raise ValueError(msg.format(c, self.header)) |
| 93 | indexes.append(self.header.index(c)) |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 94 | frames = [[f[i] for i in indexes] for f in self.frames] |
Sergei Trofimov | d952abf | 2017-09-19 13:48:08 +0100 | [diff] [blame] | 95 | header = columns |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 96 | with open(outfile, 'w') as wfh: |
| 97 | writer = csv.writer(wfh) |
| 98 | if header: |
| 99 | writer.writerow(header) |
| 100 | writer.writerows(frames) |
| 101 | |
| 102 | def collect_frames(self, wfh): |
| 103 | raise NotImplementedError() |
| 104 | |
| 105 | def clear(self): |
| 106 | raise NotImplementedError() |
| 107 | |
| 108 | def _process_raw_file(self, fh): |
| 109 | raise NotImplementedError() |
| 110 | |
| 111 | |
Sergei Trofimov | 2b3cee6 | 2017-06-06 14:47:42 +0100 | [diff] [blame] | 112 | class SurfaceFlingerFrameCollector(FrameCollector): |
| 113 | |
| 114 | def __init__(self, target, period, view, header=None): |
| 115 | super(SurfaceFlingerFrameCollector, self).__init__(target, period) |
| 116 | self.view = view |
| 117 | self.header = header or SurfaceFlingerFrame._fields |
| 118 | |
| 119 | def collect_frames(self, wfh): |
| 120 | for activity in self.list(): |
| 121 | if activity == self.view: |
| 122 | wfh.write(self.get_latencies(activity)) |
| 123 | |
| 124 | def clear(self): |
| 125 | self.target.execute('dumpsys SurfaceFlinger --latency-clear ') |
| 126 | |
| 127 | def get_latencies(self, activity): |
| 128 | cmd = 'dumpsys SurfaceFlinger --latency "{}"' |
| 129 | return self.target.execute(cmd.format(activity)) |
| 130 | |
| 131 | def list(self): |
Sergei Trofimov | 50dfb29 | 2017-09-13 11:36:41 +0100 | [diff] [blame] | 132 | text = self.target.execute('dumpsys SurfaceFlinger --list') |
| 133 | return text.replace('\r\n', '\n').replace('\r', '\n').split('\n') |
Sergei Trofimov | 2b3cee6 | 2017-06-06 14:47:42 +0100 | [diff] [blame] | 134 | |
| 135 | def _process_raw_file(self, fh): |
| 136 | text = fh.read().replace('\r\n', '\n').replace('\r', '\n') |
| 137 | for line in text.split('\n'): |
| 138 | line = line.strip() |
| 139 | if line: |
| 140 | self._process_trace_line(line) |
| 141 | |
| 142 | def _process_trace_line(self, line): |
| 143 | parts = line.split() |
| 144 | if len(parts) == 3: |
| 145 | frame = SurfaceFlingerFrame(*map(int, parts)) |
| 146 | if not frame.frame_ready_time: |
| 147 | return # "null" frame |
| 148 | if frame.frame_ready_time <= self.last_ready_time: |
| 149 | return # duplicate frame |
| 150 | if (frame.frame_ready_time - frame.desired_present_time) > self.drop_threshold: |
| 151 | logger.debug('Dropping bogus frame {}.'.format(line)) |
| 152 | return # bogus data |
| 153 | self.last_ready_time = frame.frame_ready_time |
| 154 | self.frames.append(frame) |
| 155 | elif len(parts) == 1: |
| 156 | self.refresh_period = int(parts[0]) |
| 157 | self.drop_threshold = self.refresh_period * 1000 |
| 158 | elif 'SurfaceFlinger appears to be unresponsive, dumping anyways' in line: |
| 159 | self.unresponsive_count += 1 |
| 160 | else: |
| 161 | logger.warning('Unexpected SurfaceFlinger dump output: {}'.format(line)) |
| 162 | |
| 163 | |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 164 | def read_gfxinfo_columns(target): |
| 165 | output = target.execute('dumpsys gfxinfo --list framestats') |
| 166 | lines = iter(output.split('\n')) |
| 167 | for line in lines: |
| 168 | if line.startswith('---PROFILEDATA---'): |
| 169 | break |
| 170 | columns_line = lines.next() |
| 171 | return columns_line.split(',')[:-1] # has a trailing ',' |
| 172 | |
| 173 | |
| 174 | class GfxinfoFrameCollector(FrameCollector): |
| 175 | |
| 176 | def __init__(self, target, period, package, header=None): |
| 177 | super(GfxinfoFrameCollector, self).__init__(target, period) |
| 178 | self.package = package |
| 179 | self.header = None |
| 180 | self._init_header(header) |
| 181 | |
| 182 | def collect_frames(self, wfh): |
| 183 | cmd = 'dumpsys gfxinfo {} framestats' |
| 184 | wfh.write(self.target.execute(cmd.format(self.package))) |
| 185 | |
| 186 | def clear(self): |
| 187 | pass |
| 188 | |
| 189 | def _init_header(self, header): |
| 190 | if header is not None: |
| 191 | self.header = header |
| 192 | else: |
| 193 | self.header = read_gfxinfo_columns(self.target) |
| 194 | |
| 195 | def _process_raw_file(self, fh): |
| 196 | found = False |
| 197 | try: |
Sergei Trofimov | 4593d86 | 2017-09-22 13:46:32 +0100 | [diff] [blame^] | 198 | last_vsync = 0 |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 199 | while True: |
| 200 | for line in fh: |
| 201 | if line.startswith('---PROFILEDATA---'): |
| 202 | found = True |
| 203 | break |
| 204 | |
| 205 | fh.next() # headers |
| 206 | for line in fh: |
| 207 | if line.startswith('---PROFILEDATA---'): |
| 208 | break |
Sergei Trofimov | 4593d86 | 2017-09-22 13:46:32 +0100 | [diff] [blame^] | 209 | entries = map(int, line.strip().split(',')[:-1]) # has a trailing ',' |
| 210 | if entries[1] <= last_vsync: |
| 211 | continue # repeat frame |
| 212 | last_vsync = entries[1] |
| 213 | self.frames.append(entries) |
Sergei Trofimov | 195085e | 2017-06-06 14:41:54 +0100 | [diff] [blame] | 214 | except StopIteration: |
| 215 | pass |
| 216 | if not found: |
| 217 | logger.warning('Could not find frames data in gfxinfo output') |
| 218 | return |
Sergei Trofimov | a8ca0fc | 2017-09-07 14:34:55 +0100 | [diff] [blame] | 219 | |
| 220 | |
| 221 | def _file_reverse_iter(fh, buf_size=1024): |
| 222 | fh.seek(0, os.SEEK_END) |
| 223 | offset = 0 |
| 224 | file_size = remaining_size = fh.tell() |
| 225 | while remaining_size > 0: |
| 226 | offset = min(file_size, offset + buf_size) |
| 227 | fh.seek(file_size - offset) |
| 228 | buf = fh.read(min(remaining_size, buf_size)) |
| 229 | remaining_size -= buf_size |
| 230 | yield buf |
| 231 | |
| 232 | |
| 233 | def gfxinfo_get_last_dump(filepath): |
| 234 | """ |
| 235 | Return the last gfxinfo dump from the frame collector's raw output. |
| 236 | |
| 237 | """ |
| 238 | record = '' |
| 239 | with open(filepath, 'r') as fh: |
| 240 | fh_iter = _file_reverse_iter(fh) |
| 241 | try: |
| 242 | while True: |
| 243 | buf = fh_iter.next() |
| 244 | ix = buf.find('** Graphics') |
| 245 | if ix >= 0: |
| 246 | return buf[ix:] + record |
| 247 | |
| 248 | ix = buf.find(' **\n') |
| 249 | if ix >= 0: |
| 250 | buf = fh_iter.next() + buf |
| 251 | ix = buf.find('** Graphics') |
| 252 | if ix < 0: |
| 253 | msg = '"{}" appears to be corrupted' |
| 254 | raise RuntimeError(msg.format(filepath)) |
| 255 | return buf[ix:] + record |
| 256 | record = buf + record |
| 257 | except StopIteration: |
| 258 | pass |