feat(benchpress): add receivedData + requestCount to PerflogMetric

Closes #5750
This commit is contained in:
Olivier Chafik 2015-12-10 01:15:55 +00:00 committed by Olivier Chafik
parent 24dcd267b8
commit fe1dd77d94
7 changed files with 234 additions and 51 deletions

View File

@ -175,6 +175,20 @@ In addition to that, one extra binding needs to be passed to benchpress in tests
benchpress.sample(bindings: [bp.bind(bp.Options.CAPTURE_FRAMES).toValue(true)], ... )
# Requests Metrics
Benchpress can also record the number of requests sent and count the received "encoded" bytes since [window.performance.timing.navigationStart](http://www.w3.org/TR/navigation-timing/#dom-performancetiming-navigationstart):
- `receivedData`: number of bytes received since the last navigation start
- `requestCount`: number of requests sent since the last navigation start
To collect these metrics, you need the following corresponding extra bindings:
benchpress.sample(bindings: [
bp.bind(bp.Options.RECEIVED_DATA).toValue(true),
bp.bind(bp.Options.REQUEST_COUNT).toValue(true)
], ... )
# Best practices
* Use normalized environments

View File

@ -26,6 +26,10 @@ export class Options {
// 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 RECEIVED_DATA() { return _RECEIVED_DATA; }
// TODO(tbosch): use static values when our transpiler supports them
static get REQUEST_COUNT() { return _REQUEST_COUNT; }
// TODO(tbosch): use static values when our transpiler supports them
static get CAPTURE_FRAMES() { return _CAPTURE_FRAMES; }
}
@ -40,6 +44,8 @@ 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 _RECEIVED_DATA = new OpaqueToken('Options.receivedData');
var _REQUEST_COUNT = new OpaqueToken('Options.requestCount');
var _CAPTURE_FRAMES = new OpaqueToken('Options.frameCapture');
var _DEFAULT_PROVIDERS = [
@ -50,5 +56,7 @@ var _DEFAULT_PROVIDERS = [
provide(_PREPARE, {useValue: false}),
provide(_MICRO_METRICS, {useValue: {}}),
provide(_NOW, {useValue: () => DateWrapper.now()}),
provide(_RECEIVED_DATA, {useValue: false}),
provide(_REQUEST_COUNT, {useValue: false}),
provide(_CAPTURE_FRAMES, {useValue: false})
];

View File

@ -36,12 +36,18 @@ export class PerflogMetric extends Metric {
**/
constructor(private _driverExtension: WebDriverExtension, private _setTimeout: Function,
private _microMetrics: {[key: string]: any}, private _forceGc: boolean,
private _captureFrames: boolean) {
private _captureFrames: boolean, private _receivedData: boolean,
private _requestCount: boolean) {
super();
this._remainingEvents = [];
this._measureCount = 0;
this._perfLogFeatures = _driverExtension.perfLogFeatures();
if (!this._perfLogFeatures.userTiming) {
// User timing is needed for navigationStart.
this._receivedData = false;
this._requestCount = false;
}
}
describe(): {[key: string]: any} {
@ -61,6 +67,12 @@ export class PerflogMetric extends Metric {
res['forcedGcAmount'] = 'forced gc amount in kbytes';
}
}
if (this._receivedData) {
res['receivedData'] = 'encoded bytes received since navigationStart';
}
if (this._requestCount) {
res['requestCount'] = 'count of requests sent since navigationStart';
}
if (this._captureFrames) {
if (!this._perfLogFeatures.frameCapture) {
var warningMsg = 'WARNING: Metric requested, but not supported by driver';
@ -188,6 +200,12 @@ export class PerflogMetric extends Metric {
result['frameTime.smooth'] = 0;
}
StringMapWrapper.forEach(this._microMetrics, (desc, name) => { result[name] = 0; });
if (this._receivedData) {
result['receivedData'] = 0;
}
if (this._requestCount) {
result['requestCount'] = 0;
}
var markStartEvent = null;
var markEndEvent = null;
@ -217,6 +235,22 @@ export class PerflogMetric extends Metric {
markEndEvent = event;
}
let isInstant = StringWrapper.equals(ph, 'I') || StringWrapper.equals(ph, 'i');
if (this._requestCount && StringWrapper.equals(name, 'sendRequest')) {
result['requestCount'] += 1;
} else if (this._receivedData && StringWrapper.equals(name, 'receivedData') && isInstant) {
result['receivedData'] += event['args']['encodedDataLength'];
} else if (StringWrapper.equals(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 (this._requestCount) {
result['requestCount'] = 0;
}
}
if (isPresent(markStartEvent) && isBlank(markEndEvent) &&
event['pid'] === markStartEvent['pid']) {
if (StringWrapper.equals(ph, 'b') && StringWrapper.equals(name, _MARK_NAME_FRAME_CAPUTRE)) {
@ -236,7 +270,7 @@ export class PerflogMetric extends Metric {
frameCaptureEndEvent = event;
}
if (StringWrapper.equals(ph, 'I') || StringWrapper.equals(ph, 'i')) {
if (isInstant) {
if (isPresent(frameCaptureStartEvent) && isBlank(frameCaptureEndEvent) &&
StringWrapper.equals(name, 'frame')) {
frameTimestamps.push(event['ts']);
@ -332,14 +366,17 @@ var _FRAME_TIME_SMOOTH_THRESHOLD = 17;
var _PROVIDERS = [
bind(PerflogMetric)
.toFactory(
(driverExtension, setTimeout, microMetrics, forceGc, captureFrames) =>
new PerflogMetric(driverExtension, setTimeout, microMetrics, forceGc, captureFrames),
(driverExtension, setTimeout, microMetrics, forceGc, captureFrames, receivedData,
requestCount) => new PerflogMetric(driverExtension, setTimeout, microMetrics, forceGc,
captureFrames, receivedData, requestCount),
[
WebDriverExtension,
_SET_TIMEOUT,
Options.MICRO_METRICS,
Options.FORCE_GC,
Options.CAPTURE_FRAMES
Options.CAPTURE_FRAMES,
Options.RECEIVED_DATA,
Options.REQUEST_COUNT
]),
provide(_SET_TIMEOUT, {useValue: (fn, millis) => TimerWrapper.setTimeout(fn, millis)})
];

View File

@ -66,12 +66,15 @@ export class PerfLogFeatures {
render: boolean;
gc: boolean;
frameCapture: boolean;
userTiming: boolean;
constructor({render = false, gc = false, frameCapture = false}:
{render?: boolean, gc?: boolean, frameCapture?: boolean} = {}) {
constructor(
{render = false, gc = false, frameCapture = false, userTiming = false}:
{render?: boolean, gc?: boolean, frameCapture?: boolean, userTiming?: boolean} = {}) {
this.render = render;
this.gc = gc;
this.frameCapture = frameCapture;
this.userTiming = userTiming;
}
}

View File

@ -193,6 +193,15 @@ export class ChromeDriverExtension extends WebDriverExtension {
this._isEvent(categories, name, ['devtools.timeline'], 'Layout') ||
this._isEvent(categories, name, ['devtools.timeline'], 'Paint')) {
return normalizeEvent(event, {'name': 'render'});
} else if (this._isEvent(categories, name, ['devtools.timeline'], 'ResourceReceivedData')) {
let normArgs = {'encodedDataLength': args['data']['encodedDataLength']};
return normalizeEvent(event, {'name': 'receivedData', 'args': normArgs});
} else if (this._isEvent(categories, name, ['devtools.timeline'], 'ResourceSendRequest')) {
let data = args['data'];
let normArgs = {'url': data['url'], 'method': data['requestMethod']};
return normalizeEvent(event, {'name': 'sendRequest', 'args': normArgs});
} else if (this._isEvent(categories, name, ['blink.user_timing'], 'navigationStart')) {
return normalizeEvent(event, {'name': name});
}
return null; // nothing useful in this event
}
@ -208,7 +217,7 @@ export class ChromeDriverExtension extends WebDriverExtension {
}
perfLogFeatures(): PerfLogFeatures {
return new PerfLogFeatures({render: true, gc: true, frameCapture: true});
return new PerfLogFeatures({render: true, gc: true, frameCapture: true, userTiming: true});
}
supports(capabilities: {[key: string]: any}): boolean {

View File

@ -32,11 +32,18 @@ export function main() {
var commandLog: any[];
var eventFactory = new TraceEventFactory('timeline', 'pid0');
function createMetric(perfLogs, microMetrics = null, perfLogFeatures = null, forceGc = null,
captureFrames = null) {
function createMetric(perfLogs, perfLogFeatures,
{microMetrics, forceGc, captureFrames, receivedData, requestCount}: {
microMetrics?: {[key: string]: string},
forceGc?: boolean,
captureFrames?: boolean,
receivedData?: boolean,
requestCount?: boolean
} = {}) {
commandLog = [];
if (isBlank(perfLogFeatures)) {
perfLogFeatures = new PerfLogFeatures({render: true, gc: true, frameCapture: true});
perfLogFeatures =
new PerfLogFeatures({render: true, gc: true, frameCapture: true, userTiming: true});
}
if (isBlank(microMetrics)) {
microMetrics = StringMapWrapper.create();
@ -59,6 +66,12 @@ export function main() {
if (isPresent(captureFrames)) {
bindings.push(bind(Options.CAPTURE_FRAMES).toValue(captureFrames));
}
if (isPresent(receivedData)) {
bindings.push(bind(Options.RECEIVED_DATA).toValue(receivedData));
}
if (isPresent(requestCount)) {
bindings.push(bind(Options.REQUEST_COUNT).toValue(requestCount));
}
return Injector.resolveAndCreate(bindings).get(PerflogMetric);
}
@ -72,20 +85,20 @@ export function main() {
}
it('should describe itself based on the perfLogFeatrues', () => {
expect(sortedKeys(createMetric([[]], null, new PerfLogFeatures()).describe()))
expect(sortedKeys(createMetric([[]], new PerfLogFeatures()).describe()))
.toEqual(['pureScriptTime', 'scriptTime']);
expect(sortedKeys(createMetric([[]], null, new PerfLogFeatures({render: true, gc: false}))
.describe()))
expect(
sortedKeys(createMetric([[]], new PerfLogFeatures({render: true, gc: false})).describe()))
.toEqual(['pureScriptTime', 'renderTime', 'scriptTime']);
expect(sortedKeys(createMetric([[]]).describe()))
expect(sortedKeys(createMetric([[]], null).describe()))
.toEqual(
['gcAmount', 'gcTime', 'majorGcTime', 'pureScriptTime', 'renderTime', 'scriptTime']);
expect(
sortedKeys(createMetric([[]], null, new PerfLogFeatures({render: true, gc: true}), true)
.describe()))
expect(sortedKeys(
createMetric([[]], new PerfLogFeatures({render: true, gc: true}), {forceGc: true})
.describe()))
.toEqual([
'forcedGcAmount',
'forcedGcTime',
@ -96,16 +109,23 @@ export function main() {
'renderTime',
'scriptTime'
]);
expect(sortedKeys(createMetric([[]], new PerfLogFeatures({userTiming: true}),
{receivedData: true, requestCount: true})
.describe()))
.toEqual(['pureScriptTime', 'receivedData', 'requestCount', 'scriptTime']);
});
it('should describe itself based on micro metrics', () => {
var description = createMetric([[]], {'myMicroMetric': 'someDesc'}).describe();
var description =
createMetric([[]], null, {microMetrics: {'myMicroMetric': 'someDesc'}}).describe();
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)
createMetric([[]], new PerfLogFeatures({frameCapture: true}), {captureFrames: true})
.describe();
expect(description['frameTime.mean']).not.toContain('WARNING');
expect(description['frameTime.best']).not.toContain('WARNING');
@ -115,7 +135,7 @@ export function main() {
it('should describe itself if frame capture is requested and not available', () => {
var description =
createMetric([[]], null, new PerfLogFeatures({frameCapture: false}), null, true)
createMetric([[]], new PerfLogFeatures({frameCapture: false}), {captureFrames: true})
.describe();
expect(description['frameTime.mean']).toContain('WARNING');
expect(description['frameTime.best']).toContain('WARNING');
@ -126,7 +146,7 @@ export function main() {
describe('beginMeasure', () => {
it('should not force gc and mark the timeline', inject([AsyncTestCompleter], (async) => {
var metric = createMetric([[]]);
var metric = createMetric([[]], null);
metric.beginMeasure().then((_) => {
expect(commandLog).toEqual([['timeBegin', 'benchpress0']]);
@ -135,7 +155,7 @@ export function main() {
}));
it('should force gc and mark the timeline', inject([AsyncTestCompleter], (async) => {
var metric = createMetric([[]], null, null, true);
var metric = createMetric([[]], null, {forceGc: true});
metric.beginMeasure().then((_) => {
expect(commandLog).toEqual([['gc'], ['timeBegin', 'benchpress0']]);
@ -157,7 +177,7 @@ export function main() {
eventFactory.markEnd('benchpress0', 10)
]
];
var metric = createMetric(events);
var metric = createMetric(events, null);
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
@ -182,7 +202,7 @@ export function main() {
],
[eventFactory.markEnd('benchpress1', 3)]
];
var metric = createMetric(events);
var metric = createMetric(events, null);
metric.beginMeasure()
.then((_) => metric.endMeasure(true))
.then((_) => metric.endMeasure(true))
@ -211,7 +231,7 @@ export function main() {
eventFactory.markEnd('benchpress0', 10)
]
];
var metric = createMetric(events);
var metric = createMetric(events, null);
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
@ -247,7 +267,7 @@ export function main() {
eventFactory.markEnd('benchpress1', 6)
]
];
var metric = createMetric(events);
var metric = createMetric(events, null);
metric.beginMeasure()
.then((_) => metric.endMeasure(true))
.then((data) => {
@ -287,7 +307,7 @@ export function main() {
});
it('should measure forced gc', inject([AsyncTestCompleter], (async) => {
var metric = createMetric(events, null, null, true);
var metric = createMetric(events, null, {forceGc: true});
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
@ -309,7 +329,7 @@ export function main() {
}));
it('should restart after the forced gc if needed', inject([AsyncTestCompleter], (async) => {
var metric = createMetric(events, null, null, true);
var metric = createMetric(events, null, {forceGc: true});
metric.beginMeasure()
.then((_) => metric.endMeasure(true))
.then((data) => {
@ -325,10 +345,20 @@ export function main() {
describe('aggregation', () => {
function aggregate(events: any[], microMetrics = null, captureFrames = null) {
function aggregate(events: any[], {microMetrics, captureFrames, receivedData, requestCount}: {
microMetrics?: {[key: string]: string},
captureFrames?: boolean,
receivedData?: boolean,
requestCount?: boolean
} = {}) {
events.unshift(eventFactory.markStart('benchpress0', 0));
events.push(eventFactory.markEnd('benchpress0', 10));
var metric = createMetric([events], microMetrics, null, null, captureFrames);
var metric = createMetric([events], null, {
microMetrics: microMetrics,
captureFrames: captureFrames,
receivedData: receivedData,
requestCount: requestCount
});
return metric.beginMeasure().then((_) => metric.endMeasure(false));
}
@ -342,7 +372,7 @@ export function main() {
eventFactory.instant('frame', 4),
eventFactory.markEnd('frameCapture', 5)
],
null, true)
{captureFrames: true})
.then((data) => {
expect(data['frameTime.mean']).toBe(((3 - 1) + (4 - 3)) / 2);
async.done();
@ -353,7 +383,7 @@ export function main() {
PromiseWrapper.catchError(
aggregate(
[eventFactory.instant('frame', 4), eventFactory.markEnd('frameCapture', 5)],
null, true),
{captureFrames: true}),
(err) => {
expect(() => { throw err; })
.toThrowError('missing start event for frame capture');
@ -365,7 +395,7 @@ export function main() {
PromiseWrapper.catchError(
aggregate(
[eventFactory.markStart('frameCapture', 3), eventFactory.instant('frame', 4)],
null, true),
{captureFrames: true}),
(err) => {
expect(() => { throw err; }).toThrowError('missing end event for frame capture');
async.done();
@ -379,7 +409,7 @@ export function main() {
eventFactory.markStart('frameCapture', 3),
eventFactory.markStart('frameCapture', 4)
],
null, true),
{captureFrames: true}),
(err) => {
expect(() => { throw err; })
.toThrowError('can capture frames only once per benchmark run');
@ -399,7 +429,7 @@ export function main() {
it('should throw if frame capture is enabled, but nothing is captured',
inject([AsyncTestCompleter], (async) => {
PromiseWrapper.catchError(aggregate([], null, true), (err) => {
PromiseWrapper.catchError(aggregate([], {captureFrames: true}), (err) => {
expect(() => { throw err; })
.toThrowError(
'frame capture requested in benchpress, but no start event was found');
@ -419,7 +449,7 @@ export function main() {
eventFactory.instant('frame', 32),
eventFactory.markEnd('frameCapture', 10)
],
null, true)
{captureFrames: true})
.then((data) => {
expect(data['frameTime.worst']).toBe(10);
expect(data['frameTime.best']).toBe(3);
@ -437,7 +467,7 @@ export function main() {
eventFactory.instant('frame', 3),
eventFactory.markEnd('frameCapture', 4)
],
null, true)
{captureFrames: true})
.then((data) => {
expect(data['frameTime.smooth']).toBe(1.0);
async.done();
@ -456,7 +486,7 @@ export function main() {
eventFactory.instant('frame', 24),
eventFactory.markEnd('frameCapture', 4)
],
null, true)
{captureFrames: true})
.then((data) => {
expect(data['frameTime.smooth']).toBe(0.75);
async.done();
@ -518,16 +548,18 @@ export function main() {
it('should ignore events from different processed as the start mark',
inject([AsyncTestCompleter], (async) => {
var otherProcessEventFactory = new TraceEventFactory('timeline', 'pid1');
var metric = createMetric([
[
eventFactory.markStart('benchpress0', 0),
eventFactory.start('script', 0, null),
eventFactory.end('script', 5, null),
otherProcessEventFactory.start('script', 10, null),
otherProcessEventFactory.end('script', 17, null),
eventFactory.markEnd('benchpress0', 20)
]
]);
var metric = createMetric(
[
[
eventFactory.markStart('benchpress0', 0),
eventFactory.start('script', 0, null),
eventFactory.end('script', 5, null),
otherProcessEventFactory.start('script', 10, null),
otherProcessEventFactory.end('script', 17, null),
eventFactory.markEnd('benchpress0', 20)
]
],
null);
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
@ -594,6 +626,44 @@ export function main() {
});
}));
describe('receivedData',
() => {it('should report received data since last navigationStart',
inject([AsyncTestCompleter], (async) => {
aggregate(
[
eventFactory.instant('receivedData', 0, {'encodedDataLength': 1}),
eventFactory.instant('navigationStart', 1),
eventFactory.instant('receivedData', 2, {'encodedDataLength': 2}),
eventFactory.instant('navigationStart', 3),
eventFactory.instant('receivedData', 4, {'encodedDataLength': 4}),
eventFactory.instant('receivedData', 5, {'encodedDataLength': 8})
],
{receivedData: true})
.then((data) => {
expect(data['receivedData']).toBe(12);
async.done();
});
}))});
describe('requestCount',
() => {it('should report count of requests sent since last navigationStart',
inject([AsyncTestCompleter], (async) => {
aggregate(
[
eventFactory.instant('sendRequest', 0),
eventFactory.instant('navigationStart', 1),
eventFactory.instant('sendRequest', 2),
eventFactory.instant('navigationStart', 3),
eventFactory.instant('sendRequest', 4),
eventFactory.instant('sendRequest', 5)
],
{requestCount: true})
.then((data) => {
expect(data['requestCount']).toBe(2);
async.done();
});
}))});
describe('microMetrics', () => {
it('should report micro metrics', inject([AsyncTestCompleter], (async) => {
@ -602,7 +672,7 @@ export function main() {
eventFactory.markStart('mm1', 0),
eventFactory.markEnd('mm1', 5),
],
{'mm1': 'micro metric 1'})
{microMetrics: {'mm1': 'micro metric 1'}})
.then((data) => {
expect(data['mm1']).toBe(5.0);
async.done();
@ -627,7 +697,7 @@ export function main() {
eventFactory.markStart('mm1*20', 0),
eventFactory.markEnd('mm1*20', 5),
],
{'mm1': 'micro metric 1'})
{microMetrics: {'mm1': 'micro metric 1'}})
.then((data) => {
expect(data['mm1']).toBe(5 / 20);
async.done();

View File

@ -44,6 +44,7 @@ export function main() {
var chrome45TimelineEvents = new TraceEventFactory('devtools.timeline', 'pid0');
var chromeTimelineV8Events = new TraceEventFactory('devtools.timeline,v8', 'pid0');
var chromeBlinkTimelineEvents = new TraceEventFactory('blink,devtools.timeline', 'pid0');
var chromeBlinkUserTimingEvents = new TraceEventFactory('blink.user_timing', 'pid0');
var benchmarkEvents = new TraceEventFactory('benchmark', 'pid0');
var normEvents = new TraceEventFactory('timeline', 'pid0');
@ -354,7 +355,48 @@ export function main() {
});
}));
it('should report navigationStart', inject([AsyncTestCompleter], (async) => {
createExtension([chromeBlinkUserTimingEvents.start('navigationStart', 1234)],
CHROME45_USER_AGENT)
.readPerfLog()
.then((events) => {
expect(events).toEqual([normEvents.start('navigationStart', 1.234)]);
async.done();
});
}));
it('should report receivedData', inject([AsyncTestCompleter], (async) => {
createExtension(
[
chrome45TimelineEvents.instant('ResourceReceivedData', 1234,
{'data': {'encodedDataLength': 987}})
],
CHROME45_USER_AGENT)
.readPerfLog()
.then((events) => {
expect(events).toEqual(
[normEvents.instant('receivedData', 1.234, {'encodedDataLength': 987})]);
async.done();
});
}));
it('should report sendRequest', inject([AsyncTestCompleter], (async) => {
createExtension(
[
chrome45TimelineEvents.instant(
'ResourceSendRequest', 1234,
{'data': {'url': 'http://here', 'requestMethod': 'GET'}})
],
CHROME45_USER_AGENT)
.readPerfLog()
.then((events) => {
expect(events).toEqual([
normEvents.instant('sendRequest', 1.234,
{'url': 'http://here', 'method': 'GET'})
]);
async.done();
});
}));
});
describe('readPerfLog (common)', () => {