feat(benchpress): add mean frame time metric

goderbauer · tbosch · commit 6834c4992d0e · 2015-06-12T12:40:46.000-07:00
This is useful to measure the smoothness of animations and scrolling actions. part of #821 closes #2474
diff --git a/modules/benchpress/src/common_options.ts b/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)
 ];
diff --git a/modules/benchpress/src/metric/perflog_metric.ts b/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))
 ];
diff --git a/modules/benchpress/src/web_driver_extension.ts b/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;
   }
 }
 
diff --git a/modules/benchpress/src/webdriver/chrome_driver_extension.ts b/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');
diff --git a/modules/benchpress/test/metric/perflog_metric_spec.ts b/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)])
diff --git a/modules/benchpress/test/trace_event_factory.ts b/modules/benchpress/test/trace_event_factory.ts
diff --git a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.ts b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.ts
