diff --git a/modules/benchpress/src/common_options.ts b/modules/benchpress/src/common_options.ts index f4810bfb03..8ab071b386 100644 --- 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 index 1044a15fda..7b61158359 100644 --- 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, private _forceGc: boolean) { + private _microMetrics: StringMap, 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,6 +171,9 @@ 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; @@ -168,6 +181,11 @@ export class PerflogMetric extends Metric { var gcTimeInScript = 0; var renderTimeInScript = 0; + var frameTimestamps = []; + var frameTimes = []; + var frameCaptureStartEvent = null; + var frameCaptureEndEvent = null; + var intervalStarts: StringMap = {}; var intervalStartCount: StringMap = {}; 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 index 743714615f..6ae1d0a9b7 100644 --- 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 index 35ed3752c8..58e7c8ac9f 100644 --- 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 { 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): 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 index 22f8c898a4..da9f8aaf23 100644 --- 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 index 3a413c4e5e..c7d074e558 100644 --- a/modules/benchpress/test/trace_event_factory.ts +++ b/modules/benchpress/test/trace_event_factory.ts @@ -25,6 +25,8 @@ export class TraceEventFactory { end(name, time, args = null) { return this.create('E', name, time, args); } + instant(name, time, args = null) { return this.create('i', name, time, args); } + complete(name, time, duration, args = null) { var res = this.create('X', name, time, args); res['dur'] = duration; diff --git a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.ts b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.ts index 97808f5a40..0593442993 100644 --- a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.ts +++ b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.ts @@ -35,6 +35,7 @@ export function main() { var v8EventsOtherProcess = new TraceEventFactory('v8', 'pid1'); var chromeTimelineEvents = new TraceEventFactory('disabled-by-default-devtools.timeline', 'pid0'); + var benchmarkEvents = new TraceEventFactory('benchmark', 'pid0'); var normEvents = new TraceEventFactory('timeline', 'pid0'); function createExtension(perfRecords = null, messageMethod = 'Tracing.dataCollected') { @@ -111,6 +112,49 @@ export function main() { async.done(); }); })); + describe('frame metrics', () => { + it('should report ImplThreadRenderingStats as frame event', + inject([AsyncTestCompleter], (async) => { + createExtension([ + benchmarkEvents.instant('BenchmarkInstrumentation::ImplThreadRenderingStats', 1100, + {'data': {'frame_count': 1}}) + ]) + .readPerfLog() + .then((events) => { + expect(events).toEqual([ + normEvents.create('i', 'frame', 1.1), + ]); + async.done(); + }); + })); + + it('should not report ImplThreadRenderingStats with zero frames', + inject([AsyncTestCompleter], (async) => { + createExtension([ + benchmarkEvents.instant('BenchmarkInstrumentation::ImplThreadRenderingStats', 1100, + {'data': {'frame_count': 0}}) + ]) + .readPerfLog() + .then((events) => { + expect(events).toEqual([]); + async.done(); + }); + })); + + it('should throw when ImplThreadRenderingStats contains more than one frame', + inject([AsyncTestCompleter], (async) => { + PromiseWrapper.catchError( + createExtension([ + benchmarkEvents.instant('BenchmarkInstrumentation::ImplThreadRenderingStats', + 1100, {'data': {'frame_count': 2}}) + ]).readPerfLog(), + (err) => { + expect(() => { throw err; }) + .toThrowError('multi-frame render stats not supported'); + async.done(); + }); + })); + }); it('should normalize "tdur" to "dur"', inject([AsyncTestCompleter], (async) => { var event = chromeTimelineEvents.create('X', 'FunctionCall', 1100, null);