refactor(benchpress): report forced gc metric separately

tbosch · tbosch · commit c671706518fa · 2015-04-30T12:15:30.000-07:00
diff --git a/modules/benchpress/src/metric/perflog_metric.js b/modules/benchpress/src/metric/perflog_metric.js
@@ -24,20 +24,22 @@ export class PerflogMetric extends Metric {
   _setTimeout:Function;
   _microMetrics:StringMap<string, string>;
   _perfLogFeatures:PerfLogFeatures;
+  _forceGc:boolean;
 
   /**
    * @param driverExtension
    * @param setTimeout
    * @param microMetrics Name and description of metrics provided via console.time / console.timeEnd
    **/
-  constructor(driverExtension:WebDriverExtension, setTimeout:Function, microMetrics:StringMap<string, string>) {
+  constructor(driverExtension:WebDriverExtension, setTimeout:Function, microMetrics:StringMap<string, string>, forceGc) {
     super();
     this._driverExtension = driverExtension;
     this._remainingEvents = [];
     this._measureCount = 0;
     this._setTimeout = setTimeout;
     this._microMetrics = microMetrics;
     this._perfLogFeatures = driverExtension.perfLogFeatures();
+    this._forceGc = forceGc;
   }
 
   describe():StringMap {
@@ -46,12 +48,16 @@ export class PerflogMetric extends Metric {
       'pureScriptTime': 'script execution time in ms, without gc nor render'
     };
     if (this._perfLogFeatures.render) {
-      res['renderTime'] = 'render time in and ouside of script in ms';
+      res['renderTime'] = 'render time in ms';
     }
     if (this._perfLogFeatures.gc) {
-      res['gcTime'] = 'gc time in and ouside of script in ms';
+      res['gcTime'] = 'gc time in ms';
       res['gcAmount'] = 'gc amount in kbytes';
       res['majorGcTime'] = 'time of major gcs in ms';
+      if (this._forceGc) {
+        res['forcedGcTime'] = 'forced gc time in ms';
+        res['forcedGcAmount'] = 'forced gc amount in kbytes';
+      }
     }
     StringMapWrapper.forEach(this._microMetrics, (desc, name) => {
       StringMapWrapper.set(res, name, desc);
@@ -60,10 +66,38 @@ export class PerflogMetric extends Metric {
   }
 
   beginMeasure():Promise {
+    var resultPromise = PromiseWrapper.resolve(null);
+    if (this._forceGc) {
+      resultPromise = resultPromise.then( (_) => this._driverExtension.gc() );
+    }
+    return resultPromise.then( (_) => this._beginMeasure() );
+  }
+
+  endMeasure(restart:boolean):Promise<StringMap> {
+    if (this._forceGc) {
+      return this._endPlainMeasureAndMeasureForceGc(restart);
+    } else {
+      return this._endMeasure(restart);
+    }
+  }
+
+  _endPlainMeasureAndMeasureForceGc(restartMeasure:boolean) {
+    return this._endMeasure(true).then( (measurValues) => {
+        return this._driverExtension.gc()
+          .then( (_) => this._endMeasure(restartMeasure) )
+          .then( (forceGcMeasureValues) => {
+            StringMapWrapper.set(measurValues, 'forcedGcTime', forceGcMeasureValues['gcTime']);
+            StringMapWrapper.set(measurValues, 'forcedGcAmount', forceGcMeasureValues['gcAmount']);
+            return measurValues;
+          });
+      });
+  }
+
+  _beginMeasure():Promise {
     return this._driverExtension.timeBegin(this._markName(this._measureCount++));
   }
 
-  endMeasure(restart:boolean):Promise<Object> {
+  _endMeasure(restart:boolean):Promise<StringMap> {
     var markName = this._markName(this._measureCount-1);
     var nextMarkName = restart ? this._markName(this._measureCount++) : null;
     return this._driverExtension.timeEnd(markName, nextMarkName)
@@ -210,9 +244,9 @@ var _MARK_NAME_PREFIX = 'benchpress';
 var _SET_TIMEOUT = new OpaqueToken('PerflogMetric.setTimeout');
 var _BINDINGS = [
   bind(PerflogMetric).toFactory(
-    (driverExtension, setTimeout, microMetrics) =>
-      new PerflogMetric(driverExtension, setTimeout, microMetrics),
-    [WebDriverExtension, _SET_TIMEOUT, Options.MICRO_METRICS]
+    (driverExtension, setTimeout, microMetrics, forceGc) =>
+      new PerflogMetric(driverExtension, setTimeout, microMetrics, forceGc),
+    [WebDriverExtension, _SET_TIMEOUT, Options.MICRO_METRICS, Options.FORCE_GC]
   ),
   bind(_SET_TIMEOUT).toValue( (fn, millis) => PromiseWrapper.setTimeout(fn, millis) )
 ];
diff --git a/modules/benchpress/src/sampler.js b/modules/benchpress/src/sampler.js
@@ -6,7 +6,6 @@ import { bind, OpaqueToken } from 'angular2/di';
 import { Metric } from './metric';
 import { Validator } from './validator';
 import { Reporter } from './reporter';
-import { WebDriverExtension } from './web_driver_extension';
 import { WebDriverAdapter } from './web_driver_adapter';
 
 import { Options } from './common_options';
@@ -25,28 +24,24 @@ export class Sampler {
   static get BINDINGS() { return _BINDINGS; }
 
   _driver:WebDriverAdapter;
-  _driverExtension:WebDriverExtension;
   _metric:Metric;
   _reporter:Reporter;
   _validator:Validator;
-  _forceGc:boolean;
   _prepare:Function;
   _execute:Function;
   _now:Function;
 
   constructor({
-    driver, driverExtension, metric, reporter, validator, forceGc, prepare, execute, now
+    driver, metric, reporter, validator, prepare, execute, now
   }:{
     driver: WebDriverAdapter,
-    driverExtension: WebDriverExtension, metric: Metric, reporter: Reporter,
+    metric: Metric, reporter: Reporter,
     validator: Validator, prepare: Function, execute: Function, now: Function
   }={}) {
     this._driver = driver;
-    this._driverExtension = driverExtension;
     this._metric = metric;
     this._reporter = reporter;
     this._validator = validator;
-    this._forceGc = forceGc;
     this._prepare = prepare;
     this._execute = execute;
     this._now = now;
@@ -64,22 +59,13 @@ export class Sampler {
           }
         });
     }
-    return this._gcIfNeeded().then( (_) => loop(new SampleState([], null)) );
-  }
-
-  _gcIfNeeded() {
-    if (this._forceGc) {
-      return this._driverExtension.gc();
-    } else {
-      return PromiseWrapper.resolve(null);
-    }
+    return loop(new SampleState([], null));
   }
 
   _iterate(lastState) {
     var resultPromise;
     if (isPresent(this._prepare)) {
-      resultPromise = this._driver.waitFor(this._prepare)
-        .then( (_) => this._gcIfNeeded() );
+      resultPromise = this._driver.waitFor(this._prepare);
     } else {
       resultPromise = PromiseWrapper.resolve(null);
     }
@@ -88,7 +74,6 @@ export class Sampler {
     }
     return resultPromise
       .then( (_) => this._driver.waitFor(this._execute) )
-      .then( (_) => this._gcIfNeeded() )
       .then( (_) => this._metric.endMeasure(isBlank(this._prepare)) )
       .then( (measureValues) => this._report(lastState, measureValues) );
   }
@@ -118,13 +103,11 @@ export class SampleState {
 
 var _BINDINGS = [
   bind(Sampler).toFactory(
-    (driver, driverExtension, metric, reporter, validator, forceGc, prepare, execute, now) => new Sampler({
+    (driver, metric, reporter, validator, prepare, execute, now) => new Sampler({
       driver: driver,
-      driverExtension: driverExtension,
       reporter: reporter,
       validator: validator,
       metric: metric,
-      forceGc: forceGc,
       // TODO(tbosch): DI right now does not support null/undefined objects
       // Mostly because the cache would have to be initialized with a
       // special null object, which is expensive.
@@ -133,8 +116,8 @@ var _BINDINGS = [
       now: now
     }),
     [
-      WebDriverAdapter, WebDriverExtension, Metric, Reporter, Validator,
-      Options.FORCE_GC, Options.PREPARE, Options.EXECUTE, Options.NOW
+      WebDriverAdapter, Metric, Reporter, Validator,
+      Options.PREPARE, Options.EXECUTE, Options.NOW
     ]
   )
 ];
diff --git a/modules/benchpress/test/metric/perflog_metric_spec.js b/modules/benchpress/test/metric/perflog_metric_spec.js
@@ -27,7 +27,7 @@ export function main() {
   var commandLog;
   var eventFactory = new TraceEventFactory('timeline', 'pid0');
 
-  function createMetric(perfLogs, microMetrics = null, perfLogFeatures = null) {
+  function createMetric(perfLogs, microMetrics = null, perfLogFeatures = null, forceGc = null) {
     commandLog = [];
     if (isBlank(perfLogFeatures)) {
       perfLogFeatures = new PerfLogFeatures({render: true, gc: true});
@@ -45,34 +45,48 @@ export function main() {
       }),
       bind(WebDriverExtension).toValue(new MockDriverExtension(perfLogs, commandLog, perfLogFeatures))
     ];
+    if (isPresent(forceGc)) {
+      ListWrapper.push(bindings, bind(Options.FORCE_GC).toValue(forceGc));
+    }
     return Injector.resolveAndCreate(bindings).get(PerflogMetric);
   }
 
   describe('perflog metric', () => {
 
-    it('should describe itself based on the perfLogFeatrues', () => {
-      expect(createMetric([[]], null, new PerfLogFeatures()).describe()).toEqual({
-        'scriptTime': 'script execution time in ms, including gc and render',
-        'pureScriptTime': 'script execution time in ms, without gc nor render'
+    function sortedKeys(stringMap) {
+      var res = [];
+      StringMapWrapper.forEach(stringMap, (_, key) => {
+        ListWrapper.push(res, key);
       });
+      res.sort();
+      return res;
+    }
+
+    it('should describe itself based on the perfLogFeatrues', () => {
+      expect(sortedKeys(createMetric([[]], null, new PerfLogFeatures()).describe())).toEqual([
+        'pureScriptTime', 'scriptTime'
+      ]);
 
-      expect(createMetric([[]], null, new PerfLogFeatures({
+      expect(sortedKeys(createMetric([[]], null, new PerfLogFeatures({
         render: true,
         gc: false
-      })).describe()).toEqual({
-        'scriptTime': 'script execution time in ms, including gc and render',
-        'pureScriptTime': 'script execution time in ms, without gc nor render',
-        'renderTime': 'render time in and ouside of script in ms',
-      });
+      })).describe())).toEqual([
+        'pureScriptTime', 'renderTime', 'scriptTime'
+      ]);
 
-      expect(createMetric([[]]).describe()).toEqual({
-        'scriptTime': 'script execution time in ms, including gc and render',
-        'pureScriptTime': 'script execution time in ms, without gc nor render',
-        'renderTime': 'render time in and ouside of script in ms',
-        'gcTime': 'gc time in and ouside of script in ms',
-        'gcAmount': 'gc amount in kbytes',
-        'majorGcTime': 'time of major gcs in ms'
-      });
+      expect(sortedKeys(createMetric([[]]).describe())).toEqual([
+        'gcAmount', 'gcTime', 'majorGcTime',
+        'pureScriptTime', 'renderTime', 'scriptTime'
+      ]);
+
+      expect(sortedKeys(createMetric([[]], null, new PerfLogFeatures({
+        render: true,
+        gc: true
+      }), true).describe())).toEqual([
+        'forcedGcAmount', 'forcedGcTime',
+        'gcAmount', 'gcTime', 'majorGcTime',
+        'pureScriptTime', 'renderTime', 'scriptTime'
+      ]);
     });
 
     it('should describe itself based on micro metrics', () => {
@@ -84,7 +98,7 @@ export function main() {
 
     describe('beginMeasure', () => {
 
-      it('should mark the timeline', inject([AsyncTestCompleter], (async) => {
+      it('should not force gc and mark the timeline', inject([AsyncTestCompleter], (async) => {
         var metric = createMetric([[]]);
         metric.beginMeasure().then((_) => {
           expect(commandLog).toEqual([['timeBegin', 'benchpress0']]);
@@ -93,6 +107,15 @@ export function main() {
         });
       }));
 
+      it('should force gc and mark the timeline', inject([AsyncTestCompleter], (async) => {
+        var metric = createMetric([[]], null, null, true);
+        metric.beginMeasure().then((_) => {
+          expect(commandLog).toEqual([['gc'], ['timeBegin', 'benchpress0']]);
+
+          async.done();
+        });
+      }));
+
     });
 
     describe('endMeasure', () => {
@@ -200,6 +223,57 @@ export function main() {
         });
       }));
 
+      describe('with forced gc', () => {
+        var events;
+        beforeEach( () => {
+          events = [
+            [
+              eventFactory.markStart('benchpress0', 0),
+              eventFactory.start('script', 4),
+              eventFactory.end('script', 6),
+              eventFactory.markEnd('benchpress0', 10),
+              eventFactory.markStart('benchpress1', 11),
+              eventFactory.start('gc', 12, {'usedHeapSize': 2500}),
+              eventFactory.end('gc', 15, {'usedHeapSize': 1000}),
+              eventFactory.markEnd('benchpress1', 20)
+            ]
+          ];
+        });
+
+        it('should measure forced gc', inject([AsyncTestCompleter], (async) => {
+          var metric = createMetric(events, null, null, true);
+          metric.beginMeasure()
+            .then( (_) => metric.endMeasure(false) )
+            .then( (data) => {
+              expect(commandLog).toEqual([
+                ['gc'],
+                ['timeBegin', 'benchpress0'],
+                ['timeEnd', 'benchpress0', 'benchpress1'],
+                'readPerfLog',
+                ['gc'],
+                ['timeEnd', 'benchpress1', null],
+                'readPerfLog'
+              ]);
+              expect(data['forcedGcTime']).toBe(3);
+              expect(data['forcedGcAmount']).toBe(1.5);
+
+              async.done();
+          });
+        }));
+
+        it('should restart after the forced gc if needed', inject([AsyncTestCompleter], (async) => {
+          var metric = createMetric(events, null, null, true);
+          metric.beginMeasure()
+            .then( (_) => metric.endMeasure(true) )
+            .then( (data) => {
+              expect(commandLog[5]).toEqual(['timeEnd', 'benchpress1', 'benchpress2']);
+
+              async.done();
+          });
+        }));
+
+      });
+
     });
 
     describe('aggregation', () => {
@@ -403,4 +477,9 @@ class MockDriverExtension extends WebDriverExtension {
       return PromiseWrapper.resolve([]);
     }
   }
+
+  gc():Promise {
+    ListWrapper.push(this._commandLog, ['gc']);
+    return PromiseWrapper.resolve(null);
+  }
 }
diff --git a/modules/benchpress/test/sampler_spec.js b/modules/benchpress/test/sampler_spec.js
