fix(benchpress): support measuring scriptTime and other metrics of page reload.
E.g. for benchmarks that measure page start time
This commit is contained in:
parent
c4114c2f66
commit
838d4bbf6c
|
@ -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]) {
|
||||
(<any>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]) {
|
||||
(<any>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) {
|
||||
|
|
|
@ -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,
|
||||
|
|
|
@ -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};
|
||||
|
|
|
@ -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 = [
|
||||
[
|
||||
|
|
|
@ -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) {
|
||||
|
|
|
@ -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();
|
||||
});
|
||||
|
|
Loading…
Reference in New Issue