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