sascha/workload-automation
1
0
Fork 0
mirror of https://github.com/ARM-software/workload-automation.git synced 2025-01-19 04:21:17 +00:00
Code Issues Releases Wiki Activity

Merge pull request #201 from jimboatarm/marker_api

Browse Source 
Add per-action instrumentation for UX performance
This commit is contained in:
Sebastian Goscik 2016-07-15 11:15:46 +02:00 committed by GitHub
commit f68cf4e317
5 changed files with 412 additions and 44 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

BIN
wlauto/common/android/BaseUiAutomation.class
View File

Binary file not shown.

42
wlauto/external/uiauto/src/com/arm/wlauto/uiauto/BaseUiAutomation.java vendored
View File

@ -27,6 +27,7 @@ import java.util.regex.Pattern;
import android.app.Activity;
import android.os.Bundle;
import android.util.Log;
// Import the uiautomator libraries
import com.android.uiautomator.core.UiObject;
@ -37,6 +38,47 @@ import com.android.uiautomator.testrunner.UiAutomatorTestCase;
public class BaseUiAutomation extends UiAutomatorTestCase {
/**
* Basic marker API for workloads to generate start and end markers for
* deliminating and timing actions. Markers are output to logcat with debug
* priority. Actions represent a series of UI interactions to time.
*
* The marker API provides a way for instruments and result processors to hook into
* per-action timings by parsing logcat logs produced per workload iteration.
*
* The marker output consists of a logcat tag 'UX_PERF' and a message. The
* message consists of a name for the action and a timestamp. The timestamp
* is separated by a single space from the name of the action.
*
* Typical usage:
*
* ActionLogger logger = ActionLogger("testTag", parameters);
* logger.start();
* // actions to be recorded
* logger.stop();
*/
public class ActionLogger {
private String testTag;
private boolean enabled;
public ActionLogger(String testTag, Bundle parameters) {
this.testTag = testTag;
this.enabled = Boolean.parseBoolean(parameters.getString("dumpsys_enabled"));
}
public void start() {
if (enabled) {
Log.d("UX_PERF", testTag + "_start " + System.nanoTime());
}
}
public void stop() throws Exception {
if (enabled) {
Log.d("UX_PERF", testTag + "_end " + System.nanoTime());
}
}
}
public void sleep(int second) {
super.sleep(second * 1000);

54
wlauto/instrumentation/fps/__init__.py
View File

@ -37,6 +37,7 @@ from wlauto.instrumentation import instrument_is_installed
from wlauto.exceptions import (InstrumentError, WorkerThreadError, ConfigError,
DeviceNotRespondingError, TimeoutError)
from wlauto.utils.types import boolean, numeric
from wlauto.utils.fps import FpsProcessor
VSYNC_INTERVAL = 16666667
@ -154,15 +155,18 @@ class FpsInstrument(Instrument):
if self.is_enabled:
data = pd.read_csv(self.outfile)
if not data.empty: # pylint: disable=maybe-no-member
per_frame_fps = self._update_stats(context, data)
fp = FpsProcessor(data)
per_frame_fps, metrics = fp.process(self.collector.refresh_period, self.drop_threshold)
fps, frame_count, janks, not_at_vsync = metrics
context.result.add_metric('FPS', fps)
context.result.add_metric('frame_count', frame_count)
context.result.add_metric('janks', janks)
context.result.add_metric('not_at_vsync', not_at_vsync)
if self.generate_csv:
per_frame_fps.to_csv(self.fps_outfile, index=False, header=True)
context.add_artifact('fps', path='fps.csv', kind='data')
else:
context.result.add_metric('FPS', float('nan'))
context.result.add_metric('frame_count', 0)
context.result.add_metric('janks', 0)
context.result.add_metric('not_at_vsync', 0)
def slow_update_result(self, context):
result = context.result
@ -180,44 +184,6 @@ class FpsInstrument(Instrument):
result.status = IterationResult.FAILED
result.add_event('Content crash detected (actual/expected frames: {:.2}).'.format(ratio))
def _update_stats(self, context, data): # pylint: disable=too-many-locals
vsync_interval = self.collector.refresh_period
# fiter out bogus frames.
actual_present_times = data.actual_present_time[data.actual_present_time != 0x7fffffffffffffff]
actual_present_time_deltas = (actual_present_times - actual_present_times.shift()).drop(0) # pylint: disable=E1103
vsyncs_to_compose = (actual_present_time_deltas / vsync_interval).apply(lambda x: int(round(x, 0)))
# drop values lower than drop_threshold FPS as real in-game frame
# rate is unlikely to drop below that (except on loading screens
# etc, which should not be factored in frame rate calculation).
per_frame_fps = (1.0 / (vsyncs_to_compose * (vsync_interval / 1e9)))
keep_filter = per_frame_fps > self.drop_threshold
filtered_vsyncs_to_compose = vsyncs_to_compose[keep_filter]
if not filtered_vsyncs_to_compose.empty:
total_vsyncs = filtered_vsyncs_to_compose.sum()
if total_vsyncs:
frame_count = filtered_vsyncs_to_compose.size
fps = 1e9 * frame_count / (vsync_interval * total_vsyncs)
context.result.add_metric('FPS', fps)
context.result.add_metric('frame_count', frame_count)
else:
context.result.add_metric('FPS', float('nan'))
context.result.add_metric('frame_count', 0)
vtc_deltas = filtered_vsyncs_to_compose - filtered_vsyncs_to_compose.shift()
vtc_deltas.index = range(0, vtc_deltas.size)
vtc_deltas = vtc_deltas.drop(0).abs()
janks = vtc_deltas.apply(lambda x: (PAUSE_LATENCY > x > 1.5) and 1 or 0).sum()
not_at_vsync = vsyncs_to_compose.apply(lambda x: (abs(x - 1.0) > EPSYLON) and 1 or 0).sum()
context.result.add_metric('janks', janks)
context.result.add_metric('not_at_vsync', not_at_vsync)
else: # no filtered_vsyncs_to_compose
context.result.add_metric('FPS', float('nan'))
context.result.add_metric('frame_count', 0)
context.result.add_metric('janks', 0)
context.result.add_metric('not_at_vsync', 0)
per_frame_fps.name = 'fps'
return per_frame_fps
class LatencyCollector(threading.Thread):

253
wlauto/result_processors/uxperf.py Normal file
View File

@ -0,0 +1,253 @@
# Copyright 2016 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 os
import re
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.utils.types import numeric, boolean
try:
import pandas as pd
except ImportError:
pd = None
class UxPerfResultProcessor(ResultProcessor):
name = 'uxperf'
description = '''
Parse logcat for UX_PERF markers to produce performance metrics for
workload actions using specified instrumentation.
An action represents a series of UI interactions to capture.
NOTE: The UX_PERF markers are turned off by default and must be enabled in
a agenda file by setting dumpsys_enabled for the workload to true.
'''
parameters = [
Parameter('add_timings', kind=boolean, default=True,
description='''
If set to ``True``, add per-action timings to result metrics.'
'''),
Parameter('add_frames', kind=boolean, default=False,
description='''
If set to ``True``, add per-action frame statistics to result
metrics. i.e. fps, frame_count, jank and not_at_vsync.
NOTE: This option requires the fps instrument to be enabled.
'''),
Parameter('drop_threshold', kind=numeric, default=5,
description='''
Data points below this FPS will be dropped as they do not
constitute "real" gameplay. The assumption being that while
actually running, the FPS in the game will not drop below X
frames per second, except on loading screens, menus, etc,
which should not contribute to FPS calculation.
'''),
Parameter('generate_csv', kind=boolean, default=True,
description='''
If set to ``True``, this will produce temporal per-action fps
data in the results directory, in a file named <action>_fps.csv.
Note: per-action fps data will appear as discrete step-like
values in order to produce a more meainingfull representation,
a rolling mean can be applied.
'''),
]
def initialize(self, context):
if not pd or LooseVersion(pd.__version__) < LooseVersion('0.13.1'):
message = ('uxperf result processor requires pandas Python package '
'(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)
def export_iteration_result(self, result, context):
parser = UxPerfParser(context)
logfile = os.path.join(context.output_directory, 'logcat.log')
framelog = os.path.join(context.output_directory, 'frames.csv')
parser.parse(logfile)
if self.add_timings:
parser.add_action_timings()
if self.add_frames:
parser.add_action_frames(framelog, self.drop_threshold, self.generate_csv)
class UxPerfParser(object):
'''
Parses logcat messages for UX Performance markers.
UX Performance markers are output from logcat under a debug priority. The
logcat tag for the marker messages is UX_PERF. The messages associated with
this tag consist of a name for the action to be recorded and a timestamp.
These fields are delimited by a single space. e.g.
<TAG> : <MESSAGE>
UX_PERF : gestures_swipe_left_start 861975087367
...
...
UX_PERF : gestures_swipe_left_end 862132085804
Timestamps are produced using the running Java Virtual Machine's
high-resolution time source, in nanoseconds.
'''
def __init__(self, context):
self.context = context
self.actions = defaultdict(list)
# regex for matching logcat message format:
# date time PID-TID/package priority/tag: message
self.regex = re.compile(r'(?P<date>\d{2}-\d{2})\s+'
'(?P<time>\d{2}:\d{2}:\d{2}\.\d{3})\s+'
'(?P<PID>\d+)\s+'
'(?P<TID>\d+)\s+'
'(?P<priority>\w)\s+'
'(?P<tag>\w+)\s+:\s+'
'(?P<message>.*$)')
def parse(self, log):
'''
Opens log file and parses UX_PERF markers.
Actions delimited by markers are captured in a dictionary with
actions mapped to timestamps.
'''
loglines = self._read(log)
timestamps = self._gen_action_timestamps(loglines)
self._group_timestamps(timestamps)
def add_action_frames(self, frames, drop_threshold, generate_csv): # pylint: disable=too-many-locals
'''
Uses FpsProcessor to parse frame.csv extracting fps, frame count, jank
and vsync metrics on a per action basis. Adds results to metrics.
'''
refresh_period = self._parse_refresh_peroid()
for action in self.actions:
df = self._create_data_dict(action, frames)
fp = FpsProcessor(pd.DataFrame(df), action=action)
per_frame_fps, metrics = fp.process(refresh_period, drop_threshold)
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
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)
def add_action_timings(self):
'''
Add simple action timings in millisecond resolution to metrics
'''
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
result.add_metric(action + "_start", start, units='ms')
result.add_metric(action + "_finish", finish, units='ms')
result.add_metric(action + "_duration", duration, units='ms')
def _gen_action_timestamps(self, lines):
'''
Parses lines and matches against logcat tag.
Yields tuple containing action and timestamp.
'''
for line in lines:
match = self.regex.match(line)
if match:
if match.group('tag') == 'UX_PERF':
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)
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()
return int(refresh_period)
def _create_data_dict(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.
'''
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
@staticmethod
def _read(log):
'''
Opens a file a yields the lines with whitespace stripped.
'''
with open(log, 'r') as rfh:
for line in rfh:
yield line.strip()
@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

107
wlauto/utils/fps.py Normal file
View File

@ -0,0 +1,107 @@
# Copyright 2016 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.
#
class FpsProcessor(object):
"""
Provide common object for processing surfaceFlinger output for frame
statistics.
This processor adds four metrics to the results:
:FPS: Frames Per Second. This is the frame rate of the workload.
:frames: The total number of frames rendered during the execution of
the workload.
:janks: The number of "janks" that occurred during execution of the
workload. Janks are sudden shifts in frame rate. They result
in a "stuttery" UI. See http://jankfree.org/jank-busters-io
:not_at_vsync: The number of frames that did not render in a single
vsync cycle.
"""
def __init__(self, data, action=None):
"""
data - a pandas.DataFrame object with frame data (e.g. frames.csv)
action - output metrics names with additional action specifier
"""
self.data = data
self.action = action
def process(self, refresh_period, drop_threshold): # pylint: disable=too-many-locals
"""
Generate frame per second (fps) and associated metrics for workload.
refresh_period - the vsync interval
drop_threshold - data points below this fps will be dropped
"""
fps = float('nan')
frame_count, janks, not_at_vsync = 0, 0, 0
vsync_interval = refresh_period
# fiter out bogus frames.
bogus_frames_filter = self.data.actual_present_time != 0x7fffffffffffffff
actual_present_times = self.data.actual_present_time[bogus_frames_filter]
actual_present_time_deltas = actual_present_times - actual_present_times.shift()
actual_present_time_deltas = actual_present_time_deltas.drop(0)
vsyncs_to_compose = actual_present_time_deltas / vsync_interval
vsyncs_to_compose.apply(lambda x: int(round(x, 0)))
# drop values lower than drop_threshold FPS as real in-game frame
# rate is unlikely to drop below that (except on loading screens
# etc, which should not be factored in frame rate calculation).
per_frame_fps = (1.0 / (vsyncs_to_compose * (vsync_interval / 1e9)))
keep_filter = per_frame_fps > drop_threshold
filtered_vsyncs_to_compose = vsyncs_to_compose[keep_filter]
per_frame_fps.name = 'fps'
if not filtered_vsyncs_to_compose.empty:
total_vsyncs = filtered_vsyncs_to_compose.sum()
frame_count = filtered_vsyncs_to_compose.size
if total_vsyncs:
fps = 1e9 * frame_count / (vsync_interval * total_vsyncs)
janks = self._calc_janks(filtered_vsyncs_to_compose)
not_at_vsync = self._calc_not_at_vsync(vsyncs_to_compose)
metrics = (fps, frame_count, janks, not_at_vsync)
return per_frame_fps, metrics
@staticmethod
def _calc_janks(filtered_vsyncs_to_compose):
"""
Internal method for calculating jank frames.
"""
pause_latency = 20
vtc_deltas = filtered_vsyncs_to_compose - filtered_vsyncs_to_compose.shift()
vtc_deltas.index = range(0, vtc_deltas.size)
vtc_deltas = vtc_deltas.drop(0).abs()
janks = vtc_deltas.apply(lambda x: (pause_latency > x > 1.5) and 1 or 0).sum()
return janks
@staticmethod
def _calc_not_at_vsync(vsyncs_to_compose):
"""
Internal method for calculating the number of frames that did not
render in a single vsync cycle.
"""
epsilon = 0.0001
func = lambda x: (abs(x - 1.0) > epsilon) and 1 or 0
not_at_vsync = vsyncs_to_compose.apply(func).sum()
return not_at_vsync