angular/modules/benchpress/test/metric/perflog_metric_spec.ts
Michael Goderbauer 35589a6b3c feat(benchpress): more smoothness metrics
Benchpress now prints out the best and worst frame time in addition to the percentage of frames that hit the target of 60fps.

It also renames 'meanFrameTime' to 'frameTime.mean'. That way, all frameTime metrics start with a common suffix and will be grouped together in the console reporter.

part of #821
2015-06-16 13:34:32 -07:00

670 lines
24 KiB
TypeScript

import {
afterEach,
AsyncTestCompleter,
beforeEach,
ddescribe,
describe,
expect,
iit,
inject,
it,
xit,
} from 'angular2/test_lib';
import {List, ListWrapper, StringMapWrapper} from 'angular2/src/facade/collection';
import {PromiseWrapper, Promise} from 'angular2/src/facade/async';
import {isPresent, isBlank} from 'angular2/src/facade/lang';
import {
Metric,
PerflogMetric,
WebDriverExtension,
PerfLogFeatures,
bind,
Injector,
Options
} from 'benchpress/common';
import {TraceEventFactory} from '../trace_event_factory';
export function main() {
var commandLog;
var eventFactory = new TraceEventFactory('timeline', 'pid0');
function createMetric(perfLogs, microMetrics = null, perfLogFeatures = null, forceGc = null,
captureFrames = null) {
commandLog = [];
if (isBlank(perfLogFeatures)) {
perfLogFeatures = new PerfLogFeatures({render: true, gc: true, frameCapture: true});
}
if (isBlank(microMetrics)) {
microMetrics = StringMapWrapper.create();
}
var bindings = [
Options.DEFAULT_BINDINGS,
PerflogMetric.BINDINGS,
bind(Options.MICRO_METRICS).toValue(microMetrics),
bind(PerflogMetric.SET_TIMEOUT)
.toValue((fn, millis) => {
ListWrapper.push(commandLog, ['setTimeout', millis]);
fn();
}),
bind(WebDriverExtension)
.toValue(new MockDriverExtension(perfLogs, commandLog, perfLogFeatures))
];
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);
}
describe('perflog metric', () => {
function sortedKeys(stringMap) {
var res = [];
StringMapWrapper.forEach(stringMap, (_, key) => { ListWrapper.push(res, key); });
res.sort();
return res;
}
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(['pureScriptTime', 'renderTime', 'scriptTime']);
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', () => {
var description = createMetric([[]], {'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)
.describe();
expect(description['frameTime.mean']).not.toContain('WARNING');
expect(description['frameTime.best']).not.toContain('WARNING');
expect(description['frameTime.worst']).not.toContain('WARNING');
expect(description['frameTime.smooth']).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['frameTime.mean']).toContain('WARNING');
expect(description['frameTime.best']).toContain('WARNING');
expect(description['frameTime.worst']).toContain('WARNING');
expect(description['frameTime.smooth']).toContain('WARNING');
});
describe('beginMeasure', () => {
it('should not force gc and mark the timeline', inject([AsyncTestCompleter], (async) => {
var metric = createMetric([[]]);
metric.beginMeasure().then((_) => {
expect(commandLog).toEqual([['timeBegin', 'benchpress0']]);
async.done();
});
}));
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', () => {
it('should mark and aggregate events in between the marks',
inject([AsyncTestCompleter], (async) => {
var events = [
[
eventFactory.markStart('benchpress0', 0),
eventFactory.start('script', 4),
eventFactory.end('script', 6),
eventFactory.markEnd('benchpress0', 10)
]
];
var metric = createMetric(events);
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
expect(commandLog)
.toEqual([
['timeBegin', 'benchpress0'],
['timeEnd', 'benchpress0', null],
'readPerfLog'
]);
expect(data['scriptTime']).toBe(2);
async.done();
});
}));
it('should restart timing', inject([AsyncTestCompleter], (async) => {
var events = [
[
eventFactory.markStart('benchpress0', 0),
eventFactory.markEnd('benchpress0', 1),
eventFactory.markStart('benchpress1', 2),
],
[eventFactory.markEnd('benchpress1', 3)]
];
var metric = createMetric(events);
metric.beginMeasure()
.then((_) => metric.endMeasure(true))
.then((_) => metric.endMeasure(true))
.then((_) => {
expect(commandLog)
.toEqual([
['timeBegin', 'benchpress0'],
['timeEnd', 'benchpress0', 'benchpress1'],
'readPerfLog',
['timeEnd', 'benchpress1', 'benchpress2'],
'readPerfLog'
]);
async.done();
});
}));
it('should loop and aggregate until the end mark is present',
inject([AsyncTestCompleter], (async) => {
var events = [
[eventFactory.markStart('benchpress0', 0), eventFactory.start('script', 1)],
[eventFactory.end('script', 2)],
[
eventFactory.start('script', 3),
eventFactory.end('script', 5),
eventFactory.markEnd('benchpress0', 10)
]
];
var metric = createMetric(events);
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
expect(commandLog)
.toEqual([
['timeBegin', 'benchpress0'],
['timeEnd', 'benchpress0', null],
'readPerfLog',
['setTimeout', 100],
'readPerfLog',
['setTimeout', 100],
'readPerfLog'
]);
expect(data['scriptTime']).toBe(3);
async.done();
});
}));
it('should store events after the end mark for the next call',
inject([AsyncTestCompleter], (async) => {
var events = [
[
eventFactory.markStart('benchpress0', 0),
eventFactory.markEnd('benchpress0', 1),
eventFactory.markStart('benchpress1', 1),
eventFactory.start('script', 1),
eventFactory.end('script', 2)
],
[
eventFactory.start('script', 3),
eventFactory.end('script', 5),
eventFactory.markEnd('benchpress1', 6)
]
];
var metric = createMetric(events);
metric.beginMeasure()
.then((_) => metric.endMeasure(true))
.then((data) => {
expect(data['scriptTime']).toBe(0);
return metric.endMeasure(true)
})
.then((data) => {
expect(commandLog)
.toEqual([
['timeBegin', 'benchpress0'],
['timeEnd', 'benchpress0', 'benchpress1'],
'readPerfLog',
['timeEnd', 'benchpress1', 'benchpress2'],
'readPerfLog'
]);
expect(data['scriptTime']).toBe(3);
async.done();
});
}));
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', () => {
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, 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['frameTime.mean']).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 calculate best and worst frame time', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.markStart('frameCapture', 0),
eventFactory.instant('frame', 1),
eventFactory.instant('frame', 9),
eventFactory.instant('frame', 15),
eventFactory.instant('frame', 18),
eventFactory.instant('frame', 28),
eventFactory.instant('frame', 32),
eventFactory.markEnd('frameCapture', 10)
],
null, true)
.then((data) => {
expect(data['frameTime.worst']).toBe(10);
expect(data['frameTime.best']).toBe(3);
async.done();
});
}));
it('should calculate percentage of smoothness to be good',
inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.markStart('frameCapture', 0),
eventFactory.instant('frame', 1),
eventFactory.instant('frame', 2),
eventFactory.instant('frame', 3),
eventFactory.markEnd('frameCapture', 4)
],
null, true)
.then((data) => {
expect(data['frameTime.smooth']).toBe(1.0);
async.done();
});
}));
it('should calculate percentage of smoothness to be bad',
inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.markStart('frameCapture', 0),
eventFactory.instant('frame', 1),
eventFactory.instant('frame', 2),
eventFactory.instant('frame', 22),
eventFactory.instant('frame', 23),
eventFactory.instant('frame', 24),
eventFactory.markEnd('frameCapture', 4)
],
null, true)
.then((data) => {
expect(data['frameTime.smooth']).toBe(0.75);
async.done();
});
}));
});
it('should report a single interval', inject([AsyncTestCompleter], (async) => {
aggregate([eventFactory.start('script', 0), eventFactory.end('script', 5)])
.then((data) => {
expect(data['scriptTime']).toBe(5);
async.done();
});
}));
it('should sum up multiple intervals', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.start('script', 0),
eventFactory.end('script', 5),
eventFactory.start('script', 10),
eventFactory.end('script', 17)
])
.then((data) => {
expect(data['scriptTime']).toBe(12);
async.done();
});
}));
it('should ignore not started intervals', inject([AsyncTestCompleter], (async) => {
aggregate([eventFactory.end('script', 10)])
.then((data) => {
expect(data['scriptTime']).toBe(0);
async.done();
});
}));
it('should ignore not ended intervals', inject([AsyncTestCompleter], (async) => {
aggregate([eventFactory.start('script', 10)])
.then((data) => {
expect(data['scriptTime']).toBe(0);
async.done();
});
}));
it('should ignore nested intervals', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.start('script', 0),
eventFactory.start('script', 5),
eventFactory.end('script', 10),
eventFactory.end('script', 17)
])
.then((data) => {
expect(data['scriptTime']).toBe(17);
async.done();
});
}));
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)
]
]);
metric.beginMeasure()
.then((_) => metric.endMeasure(false))
.then((data) => {
expect(data['scriptTime']).toBe(5);
async.done();
});
}));
it('should support scriptTime metric', inject([AsyncTestCompleter], (async) => {
aggregate([eventFactory.start('script', 0), eventFactory.end('script', 5)])
.then((data) => {
expect(data['scriptTime']).toBe(5);
async.done();
});
}));
it('should support renderTime metric', inject([AsyncTestCompleter], (async) => {
aggregate([eventFactory.start('render', 0), eventFactory.end('render', 5)])
.then((data) => {
expect(data['renderTime']).toBe(5);
async.done();
});
}));
it('should support gcTime/gcAmount metric', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.start('gc', 0, {'usedHeapSize': 2500}),
eventFactory.end('gc', 5, {'usedHeapSize': 1000})
])
.then((data) => {
expect(data['gcTime']).toBe(5);
expect(data['gcAmount']).toBe(1.5);
expect(data['majorGcTime']).toBe(0);
async.done();
});
}));
it('should support majorGcTime metric', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.start('gc', 0, {'usedHeapSize': 2500}),
eventFactory.end('gc', 5, {'usedHeapSize': 1000, 'majorGc': true})
])
.then((data) => {
expect(data['gcTime']).toBe(5);
expect(data['majorGcTime']).toBe(5);
async.done();
});
}));
it('should support pureScriptTime = scriptTime-gcTime-renderTime',
inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.start('script', 0),
eventFactory.start('gc', 1, {'usedHeapSize': 1000}),
eventFactory.end('gc', 4, {'usedHeapSize': 0}),
eventFactory.start('render', 4),
eventFactory.end('render', 5),
eventFactory.end('script', 6)
])
.then((data) => {
expect(data['scriptTime']).toBe(6);
expect(data['pureScriptTime']).toBe(2);
async.done();
});
}));
describe('microMetrics', () => {
it('should report micro metrics', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.markStart('mm1', 0),
eventFactory.markEnd('mm1', 5),
],
{'mm1': 'micro metric 1'})
.then((data) => {
expect(data['mm1']).toBe(5.0);
async.done();
});
}));
it('should ignore micro metrics that were not specified',
inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.markStart('mm1', 0),
eventFactory.markEnd('mm1', 5),
])
.then((data) => {
expect(data['mm1']).toBeFalsy();
async.done();
});
}));
it('should report micro metric averages', inject([AsyncTestCompleter], (async) => {
aggregate([
eventFactory.markStart('mm1*20', 0),
eventFactory.markEnd('mm1*20', 5),
],
{'mm1': 'micro metric 1'})
.then((data) => {
expect(data['mm1']).toBe(5 / 20);
async.done();
});
}));
});
});
});
}
class MockDriverExtension extends WebDriverExtension {
constructor(private _perfLogs: List<any>, private _commandLog: List<any>,
private _perfLogFeatures: PerfLogFeatures) {
super();
}
timeBegin(name): Promise<any> {
ListWrapper.push(this._commandLog, ['timeBegin', name]);
return PromiseWrapper.resolve(null);
}
timeEnd(name, restartName): Promise<any> {
ListWrapper.push(this._commandLog, ['timeEnd', name, restartName]);
return PromiseWrapper.resolve(null);
}
perfLogFeatures(): PerfLogFeatures { return this._perfLogFeatures; }
readPerfLog(): Promise<any> {
ListWrapper.push(this._commandLog, 'readPerfLog');
if (this._perfLogs.length > 0) {
var next = this._perfLogs[0];
ListWrapper.removeAt(this._perfLogs, 0);
return PromiseWrapper.resolve(next);
} else {
return PromiseWrapper.resolve([]);
}
}
gc(): Promise<any> {
ListWrapper.push(this._commandLog, ['gc']);
return PromiseWrapper.resolve(null);
}
}