feat(benchpress): add mean frame time metric

This is useful to measure the smoothness of animations and scrolling actions. part of angular#821 closes angular#2474

Author: goderbauer

modules/benchpress/src/common_options.ts

@@ -25,6 +25,8 @@ export class Options {
  static get WRITE_FILE() { return _WRITE_FILE; }
  // TODO(tbosch): use static values when our transpiler supports them
  static get MICRO_METRICS() { return _MICRO_METRICS; }
+ // TODO(tbosch): use static values when our transpiler supports them
+ static get CAPTURE_FRAMES() { return _CAPTURE_FRAMES; }
 }
 
 var _SAMPLE_ID = new OpaqueToken('Options.sampleId');
@@ -38,6 +40,7 @@ var _USER_AGENT = new OpaqueToken('Options.userAgent');
 var _MICRO_METRICS = new OpaqueToken('Options.microMetrics');
 var _NOW = new OpaqueToken('Options.now');
 var _WRITE_FILE = new OpaqueToken('Options.writeFile');
+var _CAPTURE_FRAMES = new OpaqueToken('Options.frameCapture');
 
 var _DEFAULT_BINDINGS = [
  bind(_DEFAULT_DESCRIPTION)
@@ -46,5 +49,6 @@ var _DEFAULT_BINDINGS = [
  bind(_FORCE_GC).toValue(false),
  bind(_PREPARE).toValue(false),
  bind(_MICRO_METRICS).toValue({}),
- bind(_NOW).toValue(() => DateWrapper.now())
+ bind(_NOW).toValue(() => DateWrapper.now()),
+ bind(_CAPTURE_FRAMES).toValue(false)
 ];

modules/benchpress/src/metric/perflog_metric.ts

@@ -35,7 +35,8 @@ export class PerflogMetric extends Metric {
  * @param microMetrics Name and description of metrics provided via console.time / console.timeEnd
  **/
  constructor(private _driverExtension: WebDriverExtension, private _setTimeout: Function,
- private _microMetrics: StringMap<string, any>, private _forceGc: boolean) {
+ private _microMetrics: StringMap<string, any>, private _forceGc: boolean,
+ private _captureFrames: boolean) {
  super();
 
  this._remainingEvents = [];
@@ -60,6 +61,11 @@ export class PerflogMetric extends Metric {
  res['forcedGcAmount'] = 'forced gc amount in kbytes';
  }
  }
+ if (this._captureFrames) {
+ res['meanFrameTime'] = this._perfLogFeatures.frameCapture ?
+ 'mean frame time in ms (target: 16.6ms for 60fps)' :
+ 'WARNING: Metric requested, but not supported by driver';
+ }
  StringMapWrapper.forEach(this._microMetrics,
  (desc, name) => { StringMapWrapper.set(res, name, desc); });
  return res;
@@ -83,9 +89,13 @@ export class PerflogMetric extends Metric {
 
  _endPlainMeasureAndMeasureForceGc(restartMeasure: boolean) {
  return this._endMeasure(true).then((measureValues) => {
+ // disable frame capture for measurments during forced gc
+ var originalFrameCaptureValue = this._captureFrames;
+ this._captureFrames = false;
  return this._driverExtension.gc()
  .then((_) => this._endMeasure(restartMeasure))
  .then((forceGcMeasureValues) => {
+ this._captureFrames = originalFrameCaptureValue;
  StringMapWrapper.set(measureValues, 'forcedGcTime', forceGcMeasureValues['gcTime']);
  StringMapWrapper.set(measureValues, 'forcedGcAmount', forceGcMeasureValues['gcAmount']);
  return measureValues;
@@ -161,13 +171,21 @@ export class PerflogMetric extends Metric {
  if (this._perfLogFeatures.render) {
  result['renderTime'] = 0;
  }
+ if (this._captureFrames) {
+ result['meanFrameTime'] = 0;
+ }
  StringMapWrapper.forEach(this._microMetrics, (desc, name) => { result[name] = 0; });
 
  var markStartEvent = null;
  var markEndEvent = null;
  var gcTimeInScript = 0;
  var renderTimeInScript = 0;
 
+ var frameTimestamps = [];
+ var frameTimes = [];
+ var frameCaptureStartEvent = null;
+ var frameCaptureEndEvent = null;
+
  var intervalStarts: StringMap<string, any> = {};
  var intervalStartCount: StringMap<string, number> = {};
  events.forEach((event) => {
@@ -185,8 +203,37 @@ export class PerflogMetric extends Metric {
  } else if (StringWrapper.equals(ph, 'e') && StringWrapper.equals(name, markName)) {
  markEndEvent = event;
  }
+
  if (isPresent(markStartEvent) && isBlank(markEndEvent) &&
  event['pid'] === markStartEvent['pid']) {
+ if (StringWrapper.equals(ph, 'b') && StringWrapper.equals(name, _MARK_NAME_FRAME_CAPUTRE)) {
+ if (isPresent(frameCaptureStartEvent)) {
+ throw new BaseException('can capture frames only once per benchmark run');
+ }
+ if (!this._captureFrames) {
+ throw new BaseException(
+ 'found start event for frame capture, but frame capture was not requested in benchpress')
+ }
+ frameCaptureStartEvent = event;
+ } else if (StringWrapper.equals(ph, 'e') &&
+ StringWrapper.equals(name, _MARK_NAME_FRAME_CAPUTRE)) {
+ if (isBlank(frameCaptureStartEvent)) {
+ throw new BaseException('missing start event for frame capture');
+ }
+ frameCaptureEndEvent = event;
+ }
+
+ if (StringWrapper.equals(ph, 'I') || StringWrapper.equals(ph, 'i')) {
+ if (isPresent(frameCaptureStartEvent) && isBlank(frameCaptureEndEvent) &&
+ StringWrapper.equals(name, 'frame')) {
+ ListWrapper.push(frameTimestamps, event['ts']);
+ if (frameTimestamps.length >= 2) {
+ ListWrapper.push(frameTimes, frameTimestamps[frameTimestamps.length - 1] -
+ frameTimestamps[frameTimestamps.length - 2]);
+ }
+ }
+ }
+
  if (StringWrapper.equals(ph, 'B') || StringWrapper.equals(ph, 'b')) {
  if (isBlank(intervalStarts[name])) {
  intervalStartCount[name] = 1;
@@ -227,8 +274,25 @@ export class PerflogMetric extends Metric {
  }
  }
  });
+ if (!isPresent(markStartEvent) || !isPresent(markEndEvent)) {
+ // not all events have been received, no further processing for now
+ return null;
+ }
+
+ if (isPresent(markEndEvent) && isPresent(frameCaptureStartEvent) &&
+ isBlank(frameCaptureEndEvent)) {
+ throw new BaseException('missing end event for frame capture');
+ }
+ if (this._captureFrames && isBlank(frameCaptureStartEvent)) {
+ throw new BaseException(
+ 'frame capture requested in benchpress, but no start event was found');
+ }
+ if (frameTimes.length > 0) {
+ result['meanFrameTime'] =
+ ListWrapper.reduce(frameTimes, (a, b) => a + b, 0) / frameTimes.length;
+ }
  result['pureScriptTime'] = result['scriptTime'] - gcTimeInScript - renderTimeInScript;
- return isPresent(markStartEvent) && isPresent(markEndEvent) ? result : null;
+ return result;
  }
 
  _markName(index) { return `${_MARK_NAME_PREFIX}${index}`; }
@@ -239,10 +303,19 @@ var _MAX_RETRY_COUNT = 20;
 var _MARK_NAME_PREFIX = 'benchpress';
 var _SET_TIMEOUT = new OpaqueToken('PerflogMetric.setTimeout');
 
+var _MARK_NAME_FRAME_CAPUTRE = 'frameCapture';
+
 var _BINDINGS = [
  bind(PerflogMetric)
- .toFactory((driverExtension, setTimeout, microMetrics, forceGc) =>
- new PerflogMetric(driverExtension, setTimeout, microMetrics, forceGc),
- [WebDriverExtension, _SET_TIMEOUT, Options.MICRO_METRICS, Options.FORCE_GC]),
+ .toFactory(
+ (driverExtension, setTimeout, microMetrics, forceGc, captureFrames) =>
+ new PerflogMetric(driverExtension, setTimeout, microMetrics, forceGc, captureFrames),
+ [
+ WebDriverExtension,
+ _SET_TIMEOUT,
+ Options.MICRO_METRICS,
+ Options.FORCE_GC,
+ Options.CAPTURE_FRAMES
+ ]),
  bind(_SET_TIMEOUT).toValue((fn, millis) => TimerWrapper.setTimeout(fn, millis))
 ];

modules/benchpress/src/web_driver_extension.ts

@@ -66,10 +66,15 @@ export class WebDriverExtension {
 export class PerfLogFeatures {
  render: boolean;
  gc: boolean;
+ frameCapture: boolean;
 
- constructor({render = false, gc = false}: {render?: boolean, gc?: boolean} = {}) {
+ constructor({render = false, gc = false,
+ frameCapture = false}: {render?: boolean,
+ gc?: boolean,
+ frameCapture?: boolean} = {}) {
  this.render = render;
  this.gc = gc;
+ this.frameCapture = frameCapture;
  }
 }
 

modules/benchpress/src/webdriver/chrome_driver_extension.ts

@@ -14,6 +14,13 @@ import {WebDriverExtension, PerfLogFeatures} from '../web_driver_extension';
 import {WebDriverAdapter} from '../web_driver_adapter';
 import {Promise} from 'angular2/src/facade/async';
 
+/**
+ * Set the following 'traceCategories' to collect metrics in Chrome:
+ * 'v8,blink.console,disabled-by-default-devtools.timeline'
+ *
+ * In order to collect the frame rate related metrics, add 'benchmark'
+ * to the list above.
+ */
 export class ChromeDriverExtension extends WebDriverExtension {
  // TODO(tbosch): use static values when our transpiler supports them
  static get BINDINGS(): List<Binding> { return _BINDINGS; }
@@ -73,12 +80,14 @@ export class ChromeDriverExtension extends WebDriverExtension {
  (isBlank(args) || isBlank(args['data']) ||
  !StringWrapper.equals(args['data']['scriptName'], 'InjectedScript'))) {
  ListWrapper.push(normalizedEvents, normalizeEvent(event, {'name': 'script'}));
+
  } else if (StringWrapper.equals(name, 'RecalculateStyles') ||
  StringWrapper.equals(name, 'Layout') ||
  StringWrapper.equals(name, 'UpdateLayerTree') ||
  StringWrapper.equals(name, 'Paint') || StringWrapper.equals(name, 'Rasterize') ||
  StringWrapper.equals(name, 'CompositeLayers')) {
  ListWrapper.push(normalizedEvents, normalizeEvent(event, {'name': 'render'}));
+
  } else if (StringWrapper.equals(name, 'GCEvent')) {
  var normArgs = {
  'usedHeapSize': isPresent(args['usedHeapSizeAfter']) ? args['usedHeapSizeAfter'] :
@@ -91,20 +100,42 @@ export class ChromeDriverExtension extends WebDriverExtension {
  ListWrapper.push(normalizedEvents,
  normalizeEvent(event, {'name': 'gc', 'args': normArgs}));
  }
+
  } else if (StringWrapper.equals(cat, 'blink.console')) {
  ListWrapper.push(normalizedEvents, normalizeEvent(event, {'name': name}));
+
  } else if (StringWrapper.equals(cat, 'v8')) {
  if (StringWrapper.equals(name, 'majorGC')) {
  if (StringWrapper.equals(ph, 'B')) {
  majorGCPids[pid] = true;
  }
  }
+
+ } else if (StringWrapper.equals(cat, 'benchmark')) {
+ if (StringWrapper.equals(name, 'BenchmarkInstrumentation::ImplThreadRenderingStats')) {
+ var frameCount = event['args']['data']['frame_count'];
+ if (frameCount > 1) {
+ throw new BaseException('multi-frame render stats not supported');
+ }
+ if (frameCount == 1) {
+ ListWrapper.push(normalizedEvents, normalizeEvent(event, {'name': 'frame'}));
+ }
+ } else if (StringWrapper.equals(name, 'BenchmarkInstrumentation::DisplayRenderingStats') ||
+ StringWrapper.equals(name, 'vsync_before')) {
+ // TODO(goderbauer): If present, these events should be used instead of
+ // BenchmarkInstrumentation::ImplThreadRenderingStats.
+ // However, they never seem to appear in practice. Maybe they appear on a different
+ // platform?
+ throw new BaseException('NYI');
+ }
  }
  });
  return normalizedEvents;
  }
 
- perfLogFeatures(): PerfLogFeatures { return new PerfLogFeatures({render: true, gc: true}); }
+ perfLogFeatures(): PerfLogFeatures {
+ return new PerfLogFeatures({render: true, gc: true, frameCapture: true});
+ }
 
  supports(capabilities: StringMap<string, any>): boolean {
  return StringWrapper.equals(capabilities['browserName'].toLowerCase(), 'chrome');

modules/benchpress/test/metric/perflog_metric_spec.ts

@@ -31,10 +31,11 @@ export function main() {
  var commandLog;
  var eventFactory = new TraceEventFactory('timeline', 'pid0');
 
- function createMetric(perfLogs, microMetrics = null, perfLogFeatures = null, forceGc = null) {
+ function createMetric(perfLogs, microMetrics = null, perfLogFeatures = null, forceGc = null,
+ captureFrames = null) {
  commandLog = [];
  if (isBlank(perfLogFeatures)) {
- perfLogFeatures = new PerfLogFeatures({render: true, gc: true});
+ perfLogFeatures = new PerfLogFeatures({render: true, gc: true, frameCapture: true});
  }
  if (isBlank(microMetrics)) {
  microMetrics = StringMapWrapper.create();
@@ -54,6 +55,9 @@ export function main() {
  if (isPresent(forceGc)) {
  ListWrapper.push(bindings, bind(Options.FORCE_GC).toValue(forceGc));
  }
+ if (isPresent(captureFrames)) {
+ ListWrapper.push(bindings, bind(Options.CAPTURE_FRAMES).toValue(captureFrames));
+ }
  return Injector.resolveAndCreate(bindings).get(PerflogMetric);
  }
 
@@ -98,6 +102,20 @@ export function main() {
  expect(description['myMicroMetric']).toEqual('someDesc');
  });
 
+ it('should describe itself if frame capture is requested and available', () => {
+ var description =
+ createMetric([[]], null, new PerfLogFeatures({frameCapture: true}), null, true)
+ .describe();
+ expect(description['meanFrameTime']).not.toContain('WARNING');
+ });
+
+ it('should describe itself if frame capture is requested and not available', () => {
+ var description =
+ createMetric([[]], null, new PerfLogFeatures({frameCapture: false}), null, true)
+ .describe();
+ expect(description['meanFrameTime']).toContain('WARNING');
+ });
+
  describe('beginMeasure', () => {
 
  it('should not force gc and mark the timeline', inject([AsyncTestCompleter], (async) => {
@@ -300,13 +318,88 @@ export function main() {
 
  describe('aggregation', () => {
 
- function aggregate(events, microMetrics = null) {
+ function aggregate(events, microMetrics = null, captureFrames = null) {
  ListWrapper.insert(events, 0, eventFactory.markStart('benchpress0', 0));
  ListWrapper.push(events, eventFactory.markEnd('benchpress0', 10));
- var metric = createMetric([events], microMetrics);
+ var metric = createMetric([events], microMetrics, null, null, captureFrames);
  return metric.beginMeasure().then((_) => metric.endMeasure(false));
  }
 
+ describe('frame metrics', () => {
+ it('should calculate mean frame time', inject([AsyncTestCompleter], (async) => {
+ aggregate([
+ eventFactory.markStart('frameCapture', 0),
+ eventFactory.instant('frame', 1),
+ eventFactory.instant('frame', 3),
+ eventFactory.instant('frame', 4),
+ eventFactory.markEnd('frameCapture', 5)
+ ],
+ null, true)
+ .then((data) => {
+ expect(data['meanFrameTime']).toBe(((3 - 1) + (4 - 3)) / 2);
+ async.done();
+ });
+ }));
+
+ it('should throw if no start event', inject([AsyncTestCompleter], (async) => {
+ PromiseWrapper.catchError(
+ aggregate(
+ [eventFactory.instant('frame', 4), eventFactory.markEnd('frameCapture', 5)],
+ null, true),
+ (err) => {
+ expect(() => { throw err; })
+ .toThrowError('missing start event for frame capture');
+ async.done();
+ });
+ }));
+
+ it('should throw if no end event', inject([AsyncTestCompleter], (async) => {
+ PromiseWrapper.catchError(
+ aggregate(
+ [eventFactory.markStart('frameCapture', 3), eventFactory.instant('frame', 4)],
+ null, true),
+ (err) => {
+ expect(() => { throw err; }).toThrowError('missing end event for frame capture');
+ async.done();
+ });
+ }));
+
+ it('should throw if trying to capture twice', inject([AsyncTestCompleter], (async) => {
+ PromiseWrapper.catchError(
+ aggregate([
+ eventFactory.markStart('frameCapture', 3),
+ eventFactory.markStart('frameCapture', 4)
+ ],
+ null, true),
+ (err) => {
+ expect(() => { throw err; })
+ .toThrowError('can capture frames only once per benchmark run');
+ async.done();
+ });
+ }));
+
+ it('should throw if trying to capture when frame capture is disabled',
+ inject([AsyncTestCompleter], (async) => {
+ PromiseWrapper.catchError(aggregate([eventFactory.markStart('frameCapture', 3)]), (err) => {
+ expect(() => { throw err; })
+ .toThrowError(
+ 'found start event for frame capture, but frame capture was not requested in benchpress');
+ async.done();
+ });
+ }));
+
+ it('should throw if frame capture is enabled, but nothing is captured',
+ inject([AsyncTestCompleter], (async) => {
+ PromiseWrapper.catchError(aggregate([], null, true), (err) => {
+ expect(() => { throw err; })
+ .toThrowError(
+ 'frame capture requested in benchpress, but no start event was found');
+ async.done();
+ });
+ }));
+
+
+ });
 
  it('should report a single interval', inject([AsyncTestCompleter], (async) => {
  aggregate([eventFactory.start('script', 0), eventFactory.end('script', 5)])