1import csv 2import logging 3import os 4import re 5import shutil 6import sys 7import tempfile 8import threading 9import time 10from collections import namedtuple, OrderedDict 11from distutils.version import LooseVersion 12 13from devlib.exception import WorkerThreadError, TargetNotRespondingError, TimeoutError 14 15 16logger = logging.getLogger('rendering') 17 18SurfaceFlingerFrame = namedtuple('SurfaceFlingerFrame', 19 'desired_present_time actual_present_time frame_ready_time') 20 21VSYNC_INTERVAL = 16666667 22 23 24class 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 112class 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 164def 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 174class 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 221def _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 233def 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