diff --git a/modules/benchpress/src/metric/perflog_metric.js b/modules/benchpress/src/metric/perflog_metric.js index dd16e161b6..77eb9a9198 100644 --- a/modules/benchpress/src/metric/perflog_metric.js +++ b/modules/benchpress/src/metric/perflog_metric.js @@ -24,13 +24,14 @@ export class PerflogMetric extends Metric { _setTimeout:Function; _microMetrics:StringMap; _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) { + constructor(driverExtension:WebDriverExtension, setTimeout:Function, microMetrics:StringMap, forceGc) { super(); this._driverExtension = driverExtension; this._remainingEvents = []; @@ -38,6 +39,7 @@ export class PerflogMetric extends Metric { 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 { + 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 { + _endMeasure(restart:boolean):Promise { 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 index 5f7a0d27dc..19fb08bf7d 100644 --- 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 index e9c4696c36..c98c541bc7 100644 --- 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; + } - expect(createMetric([[]], null, new PerfLogFeatures({ + it('should describe itself based on the perfLogFeatrues', () => { + expect(sortedKeys(createMetric([[]], null, new PerfLogFeatures()).describe())).toEqual([ + 'pureScriptTime', 'scriptTime' + ]); + + 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 index b941d0023b..f4bab21ec6 100644 --- a/modules/benchpress/test/sampler_spec.js +++ b/modules/benchpress/test/sampler_spec.js @@ -16,7 +16,7 @@ import { ListWrapper, List } from 'angular2/src/facade/collection'; import { PromiseWrapper, Promise } from 'angular2/src/facade/async'; import { - Sampler, WebDriverAdapter, WebDriverExtension, + Sampler, WebDriverAdapter, Validator, Metric, Reporter, Browser, bind, Injector, Options, MeasureValues } from 'benchpress/common'; @@ -29,11 +29,9 @@ export function main() { function createSampler({ driver, - driverExtension, metric, reporter, validator, - forceGc, prepare, execute } = {}) { @@ -47,16 +45,12 @@ export function main() { if (isBlank(driver)) { driver = new MockDriverAdapter([]); } - if (isBlank(driverExtension)) { - driverExtension = new MockDriverExtension([]); - } var bindings = [ Options.DEFAULT_BINDINGS, Sampler.BINDINGS, bind(Metric).toValue(metric), bind(Reporter).toValue(reporter), bind(WebDriverAdapter).toValue(driver), - bind(WebDriverExtension).toValue(driverExtension), bind(Options.EXECUTE).toValue(execute), bind(Validator).toValue(validator), bind(Options.NOW).toValue( () => DateWrapper.fromMillis(time++) ) @@ -64,9 +58,6 @@ export function main() { if (isPresent(prepare)) { ListWrapper.push(bindings, bind(Options.PREPARE).toValue(prepare)); } - if (isPresent(forceGc)) { - ListWrapper.push(bindings, bind(Options.FORCE_GC).toValue(forceGc)); - } sampler = Injector.resolveAndCreate(bindings).get(Sampler); } @@ -97,13 +88,11 @@ export function main() { })); - it('should call prepare, gc, beginMeasure, execute, gc, endMeasure for every iteration', inject([AsyncTestCompleter], (async) => { + it('should call prepare, beginMeasure, execute, endMeasure for every iteration', inject([AsyncTestCompleter], (async) => { var workCount = 0; var log = []; createSampler({ - forceGc: true, metric: createCountingMetric(log), - driverExtension: new MockDriverExtension(log), validator: createCountingValidator(2), prepare: () => { ListWrapper.push(log, `p${workCount++}`); @@ -114,31 +103,24 @@ export function main() { }); sampler.sample().then( (_) => { expect(log).toEqual([ - ['gc'], 'p0', - ['gc'], ['beginMeasure'], 'w1', - ['gc'], ['endMeasure', false, {'script': 0}], 'p2', - ['gc'], ['beginMeasure'], 'w3', - ['gc'], ['endMeasure', false, {'script': 1}], ]); async.done(); }); })); - it('should call execute, gc, endMeasure for every iteration if there is no prepare callback', inject([AsyncTestCompleter], (async) => { + it('should call execute, endMeasure for every iteration if there is no prepare callback', inject([AsyncTestCompleter], (async) => { var log = []; var workCount = 0; createSampler({ - forceGc: true, metric: createCountingMetric(log), - driverExtension: new MockDriverExtension(log), validator: createCountingValidator(2), execute: () => { ListWrapper.push(log, `w${workCount++}`); @@ -147,34 +129,16 @@ export function main() { }); sampler.sample().then( (_) => { expect(log).toEqual([ - ['gc'], ['beginMeasure'], 'w0', - ['gc'], ['endMeasure', true, {'script': 0}], 'w1', - ['gc'], ['endMeasure', true, {'script': 1}], ]); async.done(); }); })); - it('should not gc if the flag is not set', inject([AsyncTestCompleter], (async) => { - var log = []; - createSampler({ - metric: createCountingMetric(), - driverExtension: new MockDriverExtension(log), - validator: createCountingValidator(2), - prepare: EMPTY_EXECUTE, - execute: EMPTY_EXECUTE - }); - sampler.sample().then( (_) => { - expect(log).toEqual([]); - async.done(); - }); - })); - it('should only collect metrics for execute and ignore metrics from prepare', inject([AsyncTestCompleter], (async) => { var scriptTime = 0; var iterationCount = 1; @@ -307,21 +271,6 @@ class MockDriverAdapter extends WebDriverAdapter { } -class MockDriverExtension extends WebDriverExtension { - _log:List; - constructor(log = null) { - super(); - if (isBlank(log)) { - log = []; - } - this._log = log; - } - gc():Promise { - ListWrapper.push(this._log, ['gc']); - return PromiseWrapper.resolve(null); - } -} - class MockValidator extends Validator { _validate:Function; _log:List;