diff --git a/modules/@angular/benchpress/src/metric/perflog_metric.ts b/modules/@angular/benchpress/src/metric/perflog_metric.ts index 6f714eb6ad..70d609deab 100644 --- a/modules/@angular/benchpress/src/metric/perflog_metric.ts +++ b/modules/@angular/benchpress/src/metric/perflog_metric.ts @@ -219,6 +219,24 @@ export class PerflogMetric extends Metric { var markStartEvent: PerfLogEvent = null; var markEndEvent: PerfLogEvent = null; + events.forEach((event) => { + var ph = event['ph']; + var name = event['name']; + if (ph === 'b' && name === markName) { + markStartEvent = event; + } else if (ph === 'I' && name === 'navigationStart') { + // if a benchmark measures reload of a page, use the last + // navigationStart as begin event + markStartEvent = event; + } else if (ph === 'e' && name === markName) { + markEndEvent = event; + } + }); + if (!markStartEvent || !markEndEvent) { + // not all events have been received, no further processing for now + return null; + } + var gcTimeInScript = 0; var renderTimeInScript = 0; @@ -229,6 +247,8 @@ export class PerflogMetric extends Metric { var intervalStarts: {[key: string]: PerfLogEvent} = {}; var intervalStartCount: {[key: string]: number} = {}; + + var inMeasureRange = false; events.forEach((event) => { var ph = event['ph']; var name = event['name']; @@ -238,102 +258,85 @@ export class PerflogMetric extends Metric { name = microIterationsMatch[1]; microIterations = parseInt(microIterationsMatch[2], 10); } - - if (ph === 'b' && name === markName) { - markStartEvent = event; - } else if (ph === 'e' && name === markName) { - markEndEvent = event; + if (event === markStartEvent) { + inMeasureRange = true; + } else if (event === markEndEvent) { + inMeasureRange = false; + } + if (!inMeasureRange || event['pid'] !== markStartEvent['pid']) { + return; } - let isInstant = ph === 'I' || ph === 'i'; if (this._requestCount && name === 'sendRequest') { result['requestCount'] += 1; - } else if (this._receivedData && name === 'receivedData' && isInstant) { + } else if (this._receivedData && name === 'receivedData' && ph === 'I') { result['receivedData'] += event['args']['encodedDataLength']; - } else if (name === 'navigationStart') { - // We count data + requests since the last navigationStart - // (there might be chrome extensions loaded by selenium before our page, so there - // will likely be more than one navigationStart). - if (this._receivedData) { - result['receivedData'] = 0; + } + if (ph === 'b' && name === _MARK_NAME_FRAME_CAPUTRE) { + if (frameCaptureStartEvent) { + throw new Error('can capture frames only once per benchmark run'); } - if (this._requestCount) { - result['requestCount'] = 0; + if (!this._captureFrames) { + throw new Error( + 'found start event for frame capture, but frame capture was not requested in benchpress'); + } + frameCaptureStartEvent = event; + } else if (ph === 'e' && name === _MARK_NAME_FRAME_CAPUTRE) { + if (!frameCaptureStartEvent) { + throw new Error('missing start event for frame capture'); + } + frameCaptureEndEvent = event; + } + + if (ph === 'I' && frameCaptureStartEvent && !frameCaptureEndEvent && name === 'frame') { + frameTimestamps.push(event['ts']); + if (frameTimestamps.length >= 2) { + frameTimes.push( + frameTimestamps[frameTimestamps.length - 1] - + frameTimestamps[frameTimestamps.length - 2]); } } - if (markStartEvent && !markEndEvent && event['pid'] === markStartEvent['pid']) { - if (ph === 'b' && name === _MARK_NAME_FRAME_CAPUTRE) { - if (frameCaptureStartEvent) { - throw new Error('can capture frames only once per benchmark run'); - } - if (!this._captureFrames) { - throw new Error( - 'found start event for frame capture, but frame capture was not requested in benchpress'); - } - frameCaptureStartEvent = event; - } else if (ph === 'e' && name === _MARK_NAME_FRAME_CAPUTRE) { - if (!frameCaptureStartEvent) { - throw new Error('missing start event for frame capture'); - } - frameCaptureEndEvent = event; - } - if (isInstant) { - if (frameCaptureStartEvent && !frameCaptureEndEvent && name === 'frame') { - frameTimestamps.push(event['ts']); - if (frameTimestamps.length >= 2) { - frameTimes.push( - frameTimestamps[frameTimestamps.length - 1] - - frameTimestamps[frameTimestamps.length - 2]); - } - } + if (ph === 'B' || ph === 'b') { + if (!intervalStarts[name]) { + intervalStartCount[name] = 1; + intervalStarts[name] = event; + } else { + intervalStartCount[name]++; } - - if (ph === 'B' || ph === 'b') { - if (!intervalStarts[name]) { - intervalStartCount[name] = 1; - intervalStarts[name] = event; - } else { - intervalStartCount[name]++; - } - } else if ((ph === 'E' || ph === 'e') && intervalStarts[name]) { - intervalStartCount[name]--; - if (intervalStartCount[name] === 0) { - var startEvent = intervalStarts[name]; - var duration = (event['ts'] - startEvent['ts']); - intervalStarts[name] = null; - if (name === 'gc') { - result['gcTime'] += duration; - var amount = - (startEvent['args']['usedHeapSize'] - event['args']['usedHeapSize']) / 1000; - result['gcAmount'] += amount; - var majorGc = event['args']['majorGc']; - if (majorGc && majorGc) { - result['majorGcTime'] += duration; - } - if (intervalStarts['script']) { - gcTimeInScript += duration; - } - } else if (name === 'render') { - result['renderTime'] += duration; - if (intervalStarts['script']) { - renderTimeInScript += duration; - } - } else if (name === 'script') { - result['scriptTime'] += duration; - } else if (this._microMetrics[name]) { - (result)[name] += duration / microIterations; + } else if ((ph === 'E' || ph === 'e') && intervalStarts[name]) { + intervalStartCount[name]--; + if (intervalStartCount[name] === 0) { + var startEvent = intervalStarts[name]; + var duration = (event['ts'] - startEvent['ts']); + intervalStarts[name] = null; + if (name === 'gc') { + result['gcTime'] += duration; + var amount = + (startEvent['args']['usedHeapSize'] - event['args']['usedHeapSize']) / 1000; + result['gcAmount'] += amount; + var majorGc = event['args']['majorGc']; + if (majorGc && majorGc) { + result['majorGcTime'] += duration; } + if (intervalStarts['script']) { + gcTimeInScript += duration; + } + } else if (name === 'render') { + result['renderTime'] += duration; + if (intervalStarts['script']) { + renderTimeInScript += duration; + } + } else if (name === 'script') { + result['scriptTime'] += duration; + } else if (this._microMetrics[name]) { + (result)[name] += duration / microIterations; } } } }); - if (!markStartEvent || !markEndEvent) { - // not all events have been received, no further processing for now - return null; - } - if (markEndEvent && frameCaptureStartEvent && !frameCaptureEndEvent) { + if (frameCaptureStartEvent && !frameCaptureEndEvent) { throw new Error('missing end event for frame capture'); } if (this._captureFrames && !frameCaptureStartEvent) { diff --git a/modules/@angular/benchpress/src/web_driver_extension.ts b/modules/@angular/benchpress/src/web_driver_extension.ts index 2d21ddd3dd..7b78043bae 100644 --- a/modules/@angular/benchpress/src/web_driver_extension.ts +++ b/modules/@angular/benchpress/src/web_driver_extension.ts @@ -15,7 +15,7 @@ export type PerfLogEvent = { [key: string]: any } & { cat?: string, - ph?: 'X' | 'B' | 'E' | 'b' | 'e' | 'i' | 'I', + ph?: 'X' | 'B' | 'E' | 'b' | 'e' | 'I', ts?: number, dur?: number, name?: string, diff --git a/modules/@angular/benchpress/src/webdriver/chrome_driver_extension.ts b/modules/@angular/benchpress/src/webdriver/chrome_driver_extension.ts index 60cf2e6589..c457cabe96 100644 --- a/modules/@angular/benchpress/src/webdriver/chrome_driver_extension.ts +++ b/modules/@angular/benchpress/src/webdriver/chrome_driver_extension.ts @@ -140,6 +140,8 @@ export class ChromeDriverExtension extends WebDriverExtension { (!args || !args['data'] || (args['data']['scriptName'] !== 'InjectedScript' && args['data']['scriptName'] !== ''))) { return normalizeEvent(event, {'name': 'script'}); + } else if (this._isEvent(categories, name, ['devtools.timeline'], 'EvaluateScript')) { + return normalizeEvent(event, {'name': 'script'}); } else if (this._isEvent( categories, name, ['devtools.timeline', 'blink'], 'UpdateLayoutTree')) { return normalizeEvent(event, {'name': 'render'}); @@ -187,6 +189,12 @@ function normalizeEvent( ph = 'b'; } else if (ph === 'F') { ph = 'e'; + } else if (ph === 'R') { + // mark events from navigation timing + ph = 'I'; + } else if (ph === 'i') { + // legacy support + ph = 'I'; } var result: {[key: string]: any} = {'pid': chromeEvent['pid'], 'ph': ph, 'cat': 'timeline', 'ts': chromeEvent['ts'] / 1000}; diff --git a/modules/@angular/benchpress/test/metric/perflog_metric_spec.ts b/modules/@angular/benchpress/test/metric/perflog_metric_spec.ts index ff5650174f..d844fdc066 100644 --- a/modules/@angular/benchpress/test/metric/perflog_metric_spec.ts +++ b/modules/@angular/benchpress/test/metric/perflog_metric_spec.ts @@ -171,6 +171,22 @@ export function main() { }); })); + it('should mark and aggregate events since navigationStart', + inject([AsyncTestCompleter], (async: AsyncTestCompleter) => { + var events = [[ + eventFactory.markStart('benchpress0', 0), eventFactory.start('script', 4), + eventFactory.end('script', 6), eventFactory.instant('navigationStart', 7), + eventFactory.start('script', 8), eventFactory.end('script', 9), + eventFactory.markEnd('benchpress0', 10) + ]]; + var metric = createMetric(events, null); + metric.beginMeasure().then((_) => metric.endMeasure(false)).then((data) => { + expect(data['scriptTime']).toBe(1); + + async.done(); + }); + })); + it('should restart timing', inject([AsyncTestCompleter], (async: AsyncTestCompleter) => { var events = [ [ diff --git a/modules/@angular/benchpress/test/trace_event_factory.ts b/modules/@angular/benchpress/test/trace_event_factory.ts index 63fa4f9d0a..ed113b51d6 100644 --- a/modules/@angular/benchpress/test/trace_event_factory.ts +++ b/modules/@angular/benchpress/test/trace_event_factory.ts @@ -30,7 +30,7 @@ export class TraceEventFactory { end(name: string, time: number, args: any = null) { return this.create('E', name, time, args); } instant(name: string, time: number, args: any = null) { - return this.create('i', name, time, args); + return this.create('I', name, time, args); } complete(name: string, time: number, duration: number, args: any = null) { diff --git a/modules/@angular/benchpress/test/webdriver/chrome_driver_extension_spec.ts b/modules/@angular/benchpress/test/webdriver/chrome_driver_extension_spec.ts index 2fc842a60a..ac7f054b86 100644 --- a/modules/@angular/benchpress/test/webdriver/chrome_driver_extension_spec.ts +++ b/modules/@angular/benchpress/test/webdriver/chrome_driver_extension_spec.ts @@ -123,6 +123,18 @@ export function main() { }); })); + it('should report EvaluateScript events as "script"', + inject([AsyncTestCompleter], (async: AsyncTestCompleter) => { + createExtension([chromeTimelineV8Events.start('EvaluateScript', 0)]) + .readPerfLog() + .then((events) => { + expect(events).toEqual([ + normEvents.start('script', 0), + ]); + async.done(); + }); + })); + it('should report minor gc', inject([AsyncTestCompleter], (async: AsyncTestCompleter) => { createExtension([ chromeTimelineV8Events.start('MinorGC', 1000, {'usedHeapSizeBefore': 1000}), @@ -192,8 +204,6 @@ export function main() { }); })); - - it('should ignore FunctionCalls from webdriver', inject([AsyncTestCompleter], (async: AsyncTestCompleter) => { createExtension([chromeTimelineV8Events.start( @@ -218,10 +228,10 @@ export function main() { it('should report navigationStart', inject([AsyncTestCompleter], (async: AsyncTestCompleter) => { - createExtension([chromeBlinkUserTimingEvents.start('navigationStart', 1234)]) + createExtension([chromeBlinkUserTimingEvents.instant('navigationStart', 1234)]) .readPerfLog() .then((events) => { - expect(events).toEqual([normEvents.start('navigationStart', 1.234)]); + expect(events).toEqual([normEvents.instant('navigationStart', 1.234)]); async.done(); }); })); @@ -290,7 +300,7 @@ export function main() { .readPerfLog() .then((events) => { expect(events).toEqual([ - normEvents.create('i', 'frame', 1.1), + normEvents.instant('frame', 1.1), ]); async.done(); });