devlib/devlib/utils/rendering.py

#    Copyright 2018 ARM Limited
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
#

import logging
import os
import shutil
import sys
import tempfile
import threading
import time
from collections import namedtuple
from pipes import quote

# pylint: disable=redefined-builtin
from devlib.exception  import WorkerThreadError, TargetNotRespondingError, TimeoutError
from devlib.utils.csvutil import csvwriter


logger = logging.getLogger('rendering')

SurfaceFlingerFrame = namedtuple('SurfaceFlingerFrame',
                                 'desired_present_time actual_present_time frame_ready_time')

VSYNC_INTERVAL = 16666667


class FrameCollector(threading.Thread):

    def __init__(self, target, period):
        super(FrameCollector, self).__init__()
        self.target = target
        self.period = period
        self.stop_signal = threading.Event()
        self.frames = []

        self.temp_file = None
        self.refresh_period = None
        self.drop_threshold = None
        self.unresponsive_count = 0
        self.last_ready_time = 0
        self.exc = None
        self.header = None

    def run(self):
        logger.debug('Frame data collection started.')
        try:
            self.stop_signal.clear()
            fd, self.temp_file = tempfile.mkstemp()
            logger.debug('temp file: {}'.format(self.temp_file))
            wfh = os.fdopen(fd, 'wb')
            try:
                while not self.stop_signal.is_set():
                    self.collect_frames(wfh)
                    time.sleep(self.period)
            finally:
                wfh.close()
        except (TargetNotRespondingError, TimeoutError):  # pylint: disable=W0703
            raise
        except Exception as e:  # pylint: disable=W0703
            logger.warning('Exception on collector thread: {}({})'.format(e.__class__.__name__, e))
            self.exc = WorkerThreadError(self.name, sys.exc_info())
        logger.debug('Frame data collection stopped.')

    def stop(self):
        self.stop_signal.set()
        self.join()
        if self.unresponsive_count:
            message = 'FrameCollector was unrepsonsive {} times.'.format(self.unresponsive_count)
            if self.unresponsive_count > 10:
                logger.warning(message)
            else:
                logger.debug(message)
        if self.exc:
            raise self.exc  # pylint: disable=E0702

    def process_frames(self, outfile=None):
        if not self.temp_file:
            raise RuntimeError('Attempting to process frames before running the collector')
        with open(self.temp_file) as fh:
            self._process_raw_file(fh)
        if outfile:
            shutil.copy(self.temp_file, outfile)
        os.unlink(self.temp_file)
        self.temp_file = None

    def write_frames(self, outfile, columns=None):
        if columns is None:
            header = self.header
            frames = self.frames
        else:
            indexes = []
            for c in columns:
                if c not in self.header:
                    msg = 'Invalid column "{}"; must be in {}'
                    raise ValueError(msg.format(c, self.header))
                indexes.append(self.header.index(c))
            frames = [[f[i] for i in indexes] for f in self.frames]
            header = columns
        with csvwriter(outfile) as writer:
            if header:
                writer.writerow(header)
            writer.writerows(frames)

    def collect_frames(self, wfh):
        raise NotImplementedError()

    def clear(self):
        raise NotImplementedError()

    def _process_raw_file(self, fh):
        raise NotImplementedError()


class SurfaceFlingerFrameCollector(FrameCollector):

    def __init__(self, target, period, view, header=None):
        super(SurfaceFlingerFrameCollector, self).__init__(target, period)
        self.view = view
        self.header = header or SurfaceFlingerFrame._fields

    def collect_frames(self, wfh):
        for activity in self.list():
            if activity == self.view:
                wfh.write(self.get_latencies(activity).encode('utf-8'))

    def clear(self):
        self.target.execute('dumpsys SurfaceFlinger --latency-clear ')

    def get_latencies(self, activity):
        cmd = 'dumpsys SurfaceFlinger --latency {}'
        return self.target.execute(cmd.format(quote(activity)))

    def list(self):
        text = self.target.execute('dumpsys SurfaceFlinger --list')
        return text.replace('\r\n', '\n').replace('\r', '\n').split('\n')

    def _process_raw_file(self, fh):
        found = False
        text = fh.read().replace('\r\n', '\n').replace('\r', '\n')
        for line in text.split('\n'):
            line = line.strip()
            if not line:
                continue
            if 'SurfaceFlinger appears to be unresponsive, dumping anyways' in line:
                self.unresponsive_count += 1
                continue
            parts = line.split()
            # We only want numerical data, ignore textual data.
            try:
                parts = list(map(int, parts))
            except ValueError:
                continue
            found = True
            self._process_trace_parts(parts)
        if not found:
            logger.warning('Could not find expected SurfaceFlinger output.')

    def _process_trace_parts(self, parts):
        if len(parts) == 3:
            frame = SurfaceFlingerFrame(*parts)
            if not frame.frame_ready_time:
                return # "null" frame
            if frame.frame_ready_time <= self.last_ready_time:
                return  # duplicate frame
            if (frame.frame_ready_time - frame.desired_present_time) > self.drop_threshold:
                logger.debug('Dropping bogus frame {}.'.format(' '.join(map(str, parts))))
                return  # bogus data
            self.last_ready_time = frame.frame_ready_time
            self.frames.append(frame)
        elif len(parts) == 1:
            self.refresh_period = parts[0]
            self.drop_threshold = self.refresh_period * 1000
        else:
            msg = 'Unexpected SurfaceFlinger dump output: {}'.format(' '.join(map(str, parts)))
            logger.warning(msg)


def read_gfxinfo_columns(target):
    output = target.execute('dumpsys gfxinfo --list framestats')
    lines = iter(output.split('\n'))
    for line in lines:
        if line.startswith('---PROFILEDATA---'):
            break
    columns_line = next(lines)
    return columns_line.split(',')[:-1]  # has a trailing ','


class GfxinfoFrameCollector(FrameCollector):

    def __init__(self, target, period, package, header=None):
        super(GfxinfoFrameCollector, self).__init__(target, period)
        self.package = package
        self.header = None
        self._init_header(header)

    def collect_frames(self, wfh):
        cmd = 'dumpsys gfxinfo {} framestats'
        result = self.target.execute(cmd.format(self.package))
        if sys.version_info[0] == 3:
            wfh.write(result.encode('utf-8'))
        else:
            wfh.write(result)

    def clear(self):
        pass

    def _init_header(self, header):
        if header is not None:
            self.header = header
        else:
            self.header = read_gfxinfo_columns(self.target)

    def _process_raw_file(self, fh):
        found = False
        try:
            last_vsync = 0
            while True:
                for line in fh:
                    if line.startswith('---PROFILEDATA---'):
                        found = True
                        break

                next(fh)  # headers
                for line in fh:
                    if line.startswith('---PROFILEDATA---'):
                        break
                    entries = list(map(int, line.strip().split(',')[:-1]))  # has a trailing ','
                    if entries[1] <= last_vsync:
                        continue  # repeat frame
                    last_vsync = entries[1]
                    self.frames.append(entries)
        except StopIteration:
            pass
        if not found:
            logger.warning('Could not find frames data in gfxinfo output')
            return


def _file_reverse_iter(fh, buf_size=1024):
    fh.seek(0, os.SEEK_END)
    offset = 0
    file_size = remaining_size = fh.tell()
    while remaining_size > 0:
        offset = min(file_size, offset + buf_size)
        fh.seek(file_size - offset)
        buf = fh.read(min(remaining_size, buf_size))
        remaining_size -= buf_size
        yield buf


def gfxinfo_get_last_dump(filepath):
    """
    Return the last gfxinfo dump from the frame collector's raw output.

    """
    record = ''
    with open(filepath, 'r') as fh:
        fh_iter = _file_reverse_iter(fh)
        try:
            while True:
                buf = next(fh_iter)
                ix = buf.find('** Graphics')
                if ix >= 0:
                    return buf[ix:] + record

                ix = buf.find(' **\n')
                if ix >= 0:
                    buf = next(fh_iter) + buf
                    ix = buf.find('** Graphics')
                    if ix < 0:
                        msg = '"{}" appears to be corrupted'
                        raise RuntimeError(msg.format(filepath))
                    return buf[ix:] + record
                record = buf + record
        except StopIteration:
            pass