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 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 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 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 206
