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 18 SurfaceFlingerFrame = namedtuple('SurfaceFlingerFrame', 19 'desired_present_time actual_present_time frame_ready_time') 20 21 VSYNC_INTERVAL = 16666667 22 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: 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)) 94 frames = [[f[i] for i in indexes] for f in self.frames] 95 header = columns 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 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): 132 text = self.target.execute('dumpsys SurfaceFlinger --list') 133 return text.replace('\r\n', '\n').replace('\r', '\n').split('\n') 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 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: 198 last_vsync = 0 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 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) 214 except StopIteration: 215 pass 216 if not found: 217 logger.warning('Could not find frames data in gfxinfo output') 218 return 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 259
