From e076d47a7b675bfdc2098924fc3a2db4bcb27bc7 Mon Sep 17 00:00:00 2001 From: Michael McGeagh Date: Tue, 8 Nov 2016 12:20:47 +0000 Subject: [PATCH] uxperf result_processor: updated for changes in FPS instrument --- wlauto/result_processors/uxperf.py | 142 ++++++++++++++--------------- 1 file changed, 69 insertions(+), 73 deletions(-) mode change 100644 => 100755 wlauto/result_processors/uxperf.py diff --git a/wlauto/result_processors/uxperf.py b/wlauto/result_processors/uxperf.py old mode 100644 new mode 100755 index 1f974a2a..fdac6435 --- a/wlauto/result_processors/uxperf.py +++ b/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.*\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