Merge pull request #281 from jimboatarm/uxperf-newfps

uxperf result_processor: updated for changes in FPS instrument

wlauto/result_processors/uxperf.py

@@ -20,8 +20,10 @@ import logging
 from collections import defaultdict
 from distutils.version import LooseVersion
 from wlauto import ResultProcessor, Parameter
-from wlauto.exceptions import ResultProcessorError
-from wlauto.utils.fps import FpsProcessor
+from wlauto.instrumentation import instrument_is_enabled
+from wlauto.instrumentation.fps import VSYNC_INTERVAL
+from wlauto.exceptions import ResultProcessorError, ConfigError
+from wlauto.utils.fps import FpsProcessor, SurfaceFlingerFrame, GfxInfoFrame
 from wlauto.utils.types import numeric, boolean
 
 try:
@@ -80,6 +82,8 @@ class UxPerfResultProcessor(ResultProcessor):
                        '(version 0.13.1 or higher) to be installed.\n'
                        'You can install it with pip, e.g. "sudo pip install pandas"')
             raise ResultProcessorError(message)
+        if self.add_frames and not instrument_is_enabled('fps'):
+            raise ConfigError('fps instrument must be enabled in order to add frames.')
 
     def export_iteration_result(self, result, context):
         parser = UxPerfParser(context)
@@ -121,7 +125,6 @@ class UxPerfParser(object):
         self.context = context
         self.actions = defaultdict(list)
         self.logger = logging.getLogger('UxPerfParser')
-
         # regex for matching logcat message format:
         self.regex = re.compile(r'UX_PERF.*?:\s*(?P<message>.*\d+$)')
 
@@ -133,8 +136,7 @@ class UxPerfParser(object):
         actions mapped to timestamps.
         '''
         loglines = self._read(log)
-        timestamps = self._gen_action_timestamps(loglines)
-        self._group_timestamps(timestamps)
+        self._gen_action_timestamps(loglines)
 
     def add_action_frames(self, frames, drop_threshold, generate_csv):  # pylint: disable=too-many-locals
         '''
@@ -145,32 +147,36 @@ class UxPerfParser(object):
 
         for action in self.actions:
             # default values
-            fps = float('nan')
-            frame_count, janks, not_at_vsync = 0, 0, 0
-            metrics = fps, frame_count, janks, not_at_vsync
+            fps, frame_count, janks, not_at_vsync = float('nan'), 0, 0, 0
+            p90, p95, p99 = [float('nan')] * 3
+            metrics = (fps, frame_count, janks, not_at_vsync)
 
-            df = self._create_data_dict(action, frames)
-            fp = FpsProcessor(pd.DataFrame(df), action=action)
-            try:
-                per_frame_fps, metrics = fp.process(refresh_period, drop_threshold)
+            df = self._create_sub_df(self.actions[action], frames)
+            if not df.empty:  # pylint: disable=maybe-no-member
+                fp = FpsProcessor(df, action=action)
+                try:
+                    per_frame_fps, metrics = fp.process(refresh_period, drop_threshold)
+                    fps, frame_count, janks, not_at_vsync = metrics
 
-                if generate_csv:
-                    name = action + '_fps'
-                    filename = name + '.csv'
-                    fps_outfile = os.path.join(self.context.output_directory, filename)
-                    per_frame_fps.to_csv(fps_outfile, index=False, header=True)
-                    self.context.add_artifact(name, path=filename, kind='data')
-            except AttributeError:
-                self.logger.warning('Non-matched timestamps in dumpsys output: action={}'
-                                    .format(action))
+                    if generate_csv:
+                        name = action + '_fps'
+                        filename = name + '.csv'
+                        fps_outfile = os.path.join(self.context.output_directory, filename)
+                        per_frame_fps.to_csv(fps_outfile, index=False, header=True)
+                        self.context.add_artifact(name, path=filename, kind='data')
 
-            fps, frame_count, janks, not_at_vsync = metrics
-            result = self.context.result
+                    p90, p95, p99 = fp.percentiles()
+                except AttributeError:
+                    self.logger.warning('Non-matched timestamps in dumpsys output: action={}'
+                                        .format(action))
 
-            result.add_metric(action + '_FPS', fps)
-            result.add_metric(action + '_frame_count', frame_count)
-            result.add_metric(action + '_janks', janks)
-            result.add_metric(action + '_not_at_vsync', not_at_vsync)
+            self.context.result.add_metric(action + '_FPS', fps)
+            self.context.result.add_metric(action + '_frame_count', frame_count)
+            self.context.result.add_metric(action + '_janks', janks, lower_is_better=True)
+            self.context.result.add_metric(action + '_not_at_vsync', not_at_vsync, lower_is_better=True)
+            self.context.result.add_metric(action + '_frame_time_90percentile', p90, 'ms', lower_is_better=True)
+            self.context.result.add_metric(action + '_frame_time_95percentile', p95, 'ms', lower_is_better=True)
+            self.context.result.add_metric(action + '_frame_time_99percentile', p99, 'ms', lower_is_better=True)
 
     def add_action_timings(self):
         '''
@@ -179,18 +185,23 @@ class UxPerfParser(object):
         for action, timestamps in self.actions.iteritems():
             # nanosecond precision, but not necessarily nanosecond resolution
             # truncate to guarantee millisecond precision
-            start, finish = tuple(int(ts[:-6]) for ts in timestamps)
-            duration = finish - start
-            result = self.context.result
+            ts_ms = tuple(int(ts[:-6]) for ts in timestamps)
+            if len(ts_ms) == 2:
+                start, finish = ts_ms
+                duration = finish - start
+                result = self.context.result
 
-            result.add_metric(action + "_start", start, units='ms')
-            result.add_metric(action + "_finish", finish, units='ms')
-            result.add_metric(action + "_duration", duration, units='ms')
+                result.add_metric(action + "_start", start, units='ms')
+                result.add_metric(action + "_finish", finish, units='ms')
+                result.add_metric(action + "_duration", duration, units='ms', lower_is_better=True)
+            else:
+                self.logger.warning('Expected two timestamps. Received {}'.format(ts_ms))
 
     def _gen_action_timestamps(self, lines):
         '''
         Parses lines and matches against logcat tag.
-        Yields tuple containing action and timestamp.
+        Groups timestamps by action name.
+        Creates a dictionary of lists with actions mapped to timestamps.
         '''
         for line in lines:
             match = self.regex.search(line)
@@ -199,44 +210,40 @@ class UxPerfParser(object):
                 message = match.group('message')
                 action_with_suffix, timestamp = message.rsplit(' ', 1)
                 action, _ = action_with_suffix.rsplit('_', 1)
-                yield action, timestamp
-
-    def _group_timestamps(self, markers):
-        '''
-        Groups timestamps by action name.
-        Creates a dictionary of lists with actions mapped to timestamps.
-        '''
-        for action, timestamp in markers:
-            self.actions[action].append(timestamp)
+                self.actions[action].append(timestamp)
 
     def _parse_refresh_peroid(self):
         '''
         Reads the first line of the raw dumpsys output for the refresh period.
         '''
         raw_path = os.path.join(self.context.output_directory, 'surfaceflinger.raw')
-        raw_lines = self._read(raw_path)
-        refresh_period = raw_lines.next()
+        if os.path.isfile(raw_path):
+            raw_lines = self._read(raw_path)
+            refresh_period = int(raw_lines.next())
+        else:
+            refresh_period = VSYNC_INTERVAL
 
-        return int(refresh_period)
+        return refresh_period
 
-    def _create_data_dict(self, action, frames):
+    def _create_sub_df(self, action, frames):
         '''
-        Creates a data dict containing surface flinger metrics for a captured
-        action. Used to create a DataFrame for use with the pandas library.
+        Creates a data frame containing fps metrics for a captured action.
         '''
-        loglines = self._read(frames)
-        loglines.next()  # skip csv header
-
-        d = defaultdict(list)
-        timestamps = self.actions[action]
-
-        for row in self._matched_rows(loglines, timestamps):
-            dpt, apt, frt = tuple(map(int, row.split(',')))
-            d["desired_present_time"].append(dpt)
-            d["actual_present_time"].append(apt)
-            d["frame_ready_time"].append(frt)
-
-        return d
+        start, end = map(int, action)
+        df = pd.read_csv(frames)
+        # SurfaceFlinger Algorithm
+        if df.columns.tolist() == list(SurfaceFlingerFrame._fields):  # pylint: disable=maybe-no-member
+            field = 'actual_present_time'
+        # GfxInfo Algorithm
+        elif df.columns.tolist() == list(GfxInfoFrame._fields):  # pylint: disable=maybe-no-member
+            field = 'FrameCompleted'
+        else:
+            field = ''
+            self.logger.error('frames.csv not in a recognised format. Cannot parse.')
+        if field:
+            df = df[start < df[field]]
+            df = df[df[field] <= end]
+        return df
 
     def _read(self, log):
         '''
@@ -248,14 +255,3 @@ class UxPerfParser(object):
                     yield line.strip()
         except IOError:
             self.logger.error('Could not open {}'.format(log))
-
-    @staticmethod
-    def _matched_rows(rows, timestamps):
-        '''
-        Helper method for matching timestamps within rows.
-        '''
-        start, finish = tuple(timestamps)
-        for row in rows:
-            _, apt, _ = row.split(',')
-            if apt >= start and apt <= finish:
-                yield row