feat(bench press): use chrome tracing protocol and initial iOS support

This commit is contained in:
Tobias Bosch 2015-02-18 14:39:52 -08:00
parent 8a3d9050d9
commit 7aa031b3d3
14 changed files with 733 additions and 332 deletions

View File

@ -138,6 +138,9 @@ class ListWrapper {
static List slice(List l, int from, int to) {
return l.sublist(from, to);
}
static void sort(List l, compareFn(a,b)) {
l.sort(compareFn);
}
}
bool isListLikeIterable(obj) => obj is Iterable;

View File

@ -185,6 +185,10 @@ export class ListWrapper {
static slice(l:List, from:int, to:int):List {
return l.slice(from, to);
}
static sort(l:List, compareFn:Function) {
l.sort(compareFn);
return l;
}
}
export function isListLikeIterable(obj):boolean {

View File

@ -10,6 +10,7 @@ export { ConsoleReporter } from './src/reporter/console_reporter';
export { SampleDescription } from './src/sample_description';
export { PerflogMetric } from './src/metric/perflog_metric';
export { ChromeDriverExtension } from './src/webdriver/chrome_driver_extension';
export { IOsDriverExtension } from './src/webdriver/ios_driver_extension';
export { Runner } from './src/runner';
export { Options } from './src/sample_options';
export { MeasureValues } from './src/measure_values';

View File

@ -1,6 +1,6 @@
import { PromiseWrapper, Promise } from 'angular2/src/facade/async';
import { isPresent, isBlank, int, BaseException, StringWrapper } from 'angular2/src/facade/lang';
import { ListWrapper, StringMap } from 'angular2/src/facade/collection';
import { ListWrapper, StringMap, StringMapWrapper } from 'angular2/src/facade/collection';
import { bind, OpaqueToken } from 'angular2/di';
import { WebDriverExtension } from '../web_driver_extension';
@ -33,9 +33,9 @@ export class PerflogMetric extends Metric {
'script': 'script execution time in ms',
'render': 'render time in ms',
'gcTime': 'gc time in ms',
'gcAmount': 'gc amount in bytes',
'gcAmount': 'gc amount in kbytes',
'gcTimeInScript': 'gc time during script execution in ms',
'gcAmountInScript': 'gc amount during script execution in bytes'
'gcAmountInScript': 'gc amount during script execution in kbytes'
};
}
@ -50,12 +50,12 @@ export class PerflogMetric extends Metric {
.then( (_) => this._readUntilEndMark(markName) );
}
_readUntilEndMark(markName:string, loopCount:int = 0) {
_readUntilEndMark(markName:string, loopCount:int = 0, startEvent = null) {
if (loopCount > _MAX_RETRY_COUNT) {
throw new BaseException(`Tried too often to get the ending mark: ${loopCount}`);
}
return this._driverExtension.readPerfLog().then( (events) => {
this._remainingEvents = ListWrapper.concat(this._remainingEvents, events);
if (loopCount > _MAX_RETRY_COUNT) {
throw new BaseException(`Tried too often to get the ending mark: ${loopCount}`);
}
this._addEvents(events);
var result = this._aggregateEvents(
this._remainingEvents, markName
);
@ -72,6 +72,34 @@ export class PerflogMetric extends Metric {
});
}
_addEvents(events) {
var needSort = false;
ListWrapper.forEach(events, (event) => {
if (StringWrapper.equals(event['ph'], 'X')) {
needSort = true;
var startEvent = {};
var endEvent = {};
StringMapWrapper.forEach(event, (value, prop) => {
startEvent[prop] = value;
endEvent[prop] = value;
});
startEvent['ph'] = 'B';
endEvent['ph'] = 'E';
endEvent['ts'] = startEvent['ts'] + startEvent['dur'];
ListWrapper.push(this._remainingEvents, startEvent);
ListWrapper.push(this._remainingEvents, endEvent);
} else {
ListWrapper.push(this._remainingEvents, event);
}
});
if (needSort) {
// Need to sort because of the ph==='X' events
ListWrapper.sort(this._remainingEvents, (a,b) => {
return a['ts'] - b['ts'];
});
}
}
_aggregateEvents(events, markName) {
var result = {
'script': 0,
@ -82,49 +110,40 @@ export class PerflogMetric extends Metric {
'gcAmountInScript': 0
};
var startMarkFound = false;
var endMarkFound = false;
if (isBlank(markName)) {
startMarkFound = true;
endMarkFound = true;
}
var markStartEvent = null;
var markEndEvent = null;
var intervalStarts = {};
events.forEach( (event) => {
var ph = event['ph'];
var name = event['name'];
var ts = event['ts'];
var args = event['args'];
if (StringWrapper.equals(ph, 'b') && StringWrapper.equals(name, markName)) {
startMarkFound = true;
markStartEvent = event;
} else if (StringWrapper.equals(ph, 'e') && StringWrapper.equals(name, markName)) {
endMarkFound = true;
markEndEvent = event;
}
if (startMarkFound && !endMarkFound) {
if (isPresent(markStartEvent) && isBlank(markEndEvent) && event['pid'] === markStartEvent['pid']) {
if (StringWrapper.equals(ph, 'B')) {
intervalStarts[name] = ts;
intervalStarts[name] = event;
} else if (StringWrapper.equals(ph, 'E') && isPresent(intervalStarts[name])) {
var diff = ts - intervalStarts[name];
var startEvent = intervalStarts[name];
var duration = event['ts'] - startEvent['ts'];
intervalStarts[name] = null;
if (StringWrapper.equals(name, 'gc')) {
result['gcTime'] += diff;
var gcAmount = 0;
if (isPresent(args)) {
gcAmount = args['amount'];
}
result['gcAmount'] += gcAmount;
result['gcTime'] += duration;
result['gcAmount'] += (startEvent['args']['usedHeapSize'] - event['args']['usedHeapSize']) / 1000;
if (isPresent(intervalStarts['script'])) {
result['gcTimeInScript'] += diff;
result['gcAmountInScript'] += gcAmount;
result['gcTimeInScript'] += duration;
result['gcAmountInScript'] += result['gcAmount'];
}
} else {
result[name] += diff;
result[name] += duration;
}
}
}
});
result['script'] -= result['gcTimeInScript'];
return startMarkFound && endMarkFound ? result : null;
return isPresent(markStartEvent) && isPresent(markEndEvent) ? result : null;
}
_markName(index) {

View File

@ -13,10 +13,6 @@ export class WebDriverExtension {
throw new BaseException('NYI');
}
timeStamp(name:string, names:List<String>):Promise {
throw new BaseException('NYI');
}
timeBegin(name):Promise {
throw new BaseException('NYI');
}
@ -27,10 +23,12 @@ export class WebDriverExtension {
/**
* Format:
* - name: event name, e.g. 'script', 'gc', ...
* - ph: phase: 'B' (begin), 'E' (end), 'b' (nestable start), 'e' (nestable end)
* - ts: timestamp, e.g. 12345
* - args: arguments, e.g. {someArg: 1}
* - cat: category of the event
* - name: event name: 'script', 'gc', 'render', ...
* - ph: phase: 'B' (begin), 'E' (end), 'b' (nestable start), 'e' (nestable end), 'X' (Complete event)
* - ts: timestamp in ms, e.g. 12345
* - pid: process id
* - args: arguments, e.g. {heapSize: 1234}
*
* Based on [Chrome Trace Event Format](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit)
**/

View File

@ -1,7 +1,7 @@
import { bind } from 'angular2/di';
import { ListWrapper } from 'angular2/src/facade/collection';
import { ListWrapper, StringMapWrapper } from 'angular2/src/facade/collection';
import {
Json, isPresent, isBlank, RegExpWrapper, StringWrapper
Json, isPresent, isBlank, RegExpWrapper, StringWrapper, BaseException, NumberWrapper
} from 'angular2/src/facade/lang';
import { WebDriverExtension } from '../web_driver_extension';
@ -9,9 +9,6 @@ import { WebDriverAdapter } from '../web_driver_adapter';
import { Promise } from 'angular2/src/facade/async';
var BEGIN_MARK_RE = RegExpWrapper.create('begin_(.*)');
var END_MARK_RE = RegExpWrapper.create('end_(.*)');
export class ChromeDriverExtension extends WebDriverExtension {
// TODO(tbosch): use static values when our transpiler supports them
static get BINDINGS() { return _BINDINGS; }
@ -28,15 +25,13 @@ export class ChromeDriverExtension extends WebDriverExtension {
}
timeBegin(name:string):Promise {
// Note: Can't use console.time / console.timeEnd as it does not show up in the perf log!
return this._driver.executeScript(`console.timeStamp('begin_${name}');`);
return this._driver.executeScript(`console.time('${name}');`);
}
timeEnd(name:string, restartName:string = null):Promise {
// Note: Can't use console.time / console.timeEnd as it does not show up in the perf log!
var script = `console.timeStamp('end_${name}');`;
var script = `console.timeEnd('${name}');`;
if (isPresent(restartName)) {
script += `console.timeStamp('begin_${restartName}');`
script += `console.time('${restartName}');`
}
return this._driver.executeScript(script);
}
@ -47,102 +42,83 @@ export class ChromeDriverExtension extends WebDriverExtension {
return this._driver.executeScript('1+1')
.then( (_) => this._driver.logs('performance') )
.then( (entries) => {
var records = [];
var events = [];
ListWrapper.forEach(entries, function(entry) {
var message = Json.parse(entry['message'])['message'];
if (StringWrapper.equals(message['method'], 'Timeline.eventRecorded')) {
ListWrapper.push(records, message['params']['record']);
if (StringWrapper.equals(message['method'], 'Tracing.dataCollected')) {
ListWrapper.push(events, message['params']);
}
if (StringWrapper.equals(message['method'], 'Tracing.bufferUsage')) {
throw new BaseException('The DevTools trace buffer filled during the test!');
}
});
return this._convertPerfRecordsToEvents(records);
return this._convertPerfRecordsToEvents(events);
});
}
_convertPerfRecordsToEvents(records, events = null) {
if (isBlank(events)) {
events = [];
_convertPerfRecordsToEvents(chromeEvents, normalizedEvents = null) {
if (isBlank(normalizedEvents)) {
normalizedEvents = [];
}
records.forEach( (record) => {
var endEvent = null;
var type = record['type'];
var data = record['data'];
var startTime = record['startTime'];
var endTime = record['endTime'];
if (StringWrapper.equals(type, 'FunctionCall') &&
(isBlank(data) || !StringWrapper.equals(data['scriptName'], 'InjectedScript'))) {
ListWrapper.push(events, {
'name': 'script',
'ts': startTime,
'ph': 'B'
});
endEvent = {
'name': 'script',
'ts': endTime,
'ph': 'E',
'args': null
chromeEvents.forEach( (event) => {
var cat = event['cat'];
var name = event['name'];
var args = event['args'];
if (StringWrapper.equals(cat, 'disabled-by-default-devtools.timeline')) {
if (StringWrapper.equals(name, 'FunctionCall') &&
(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')) {
ListWrapper.push(normalizedEvents, normalizeEvent(event, {
'name': 'gc',
'args': {
'usedHeapSize': isPresent(args['usedHeapSizeAfter']) ? args['usedHeapSizeAfter'] : args['usedHeapSizeBefore']
}
}));
}
} else if (StringWrapper.equals(type, 'TimeStamp')) {
var name = data['message'];
var ph;
var match = RegExpWrapper.firstMatch(BEGIN_MARK_RE, name);
if (isPresent(match)) {
ph = 'b';
} else {
match = RegExpWrapper.firstMatch(END_MARK_RE, name);
if (isPresent(match)) {
ph = 'e';
}
}
if (isPresent(ph)) {
ListWrapper.push(events, {
'name': match[1],
'ph': ph
});
}
} else if (StringWrapper.equals(type, 'RecalculateStyles') ||
StringWrapper.equals(type, 'Layout') ||
StringWrapper.equals(type, 'UpdateLayerTree') ||
StringWrapper.equals(type, 'Paint') ||
StringWrapper.equals(type, 'Rasterize') ||
StringWrapper.equals(type, 'CompositeLayers')) {
ListWrapper.push(events, {
'name': 'render',
'ts': startTime,
'ph': 'B'
});
endEvent = {
'name': 'render',
'ts': endTime,
'ph': 'E',
'args': null
}
} else if (StringWrapper.equals(type, 'GCEvent')) {
ListWrapper.push(events, {
'name': 'gc',
'ts': startTime,
'ph': 'B'
});
endEvent = {
'name': 'gc',
'ts': endTime,
'ph': 'E',
'args': {
'amount': data['usedHeapSizeDelta']
}
};
}
if (isPresent(record['children'])) {
this._convertPerfRecordsToEvents(record['children'], events);
}
if (isPresent(endEvent)) {
ListWrapper.push(events, endEvent);
} else if (StringWrapper.equals(cat, 'blink.console')) {
ListWrapper.push(normalizedEvents, normalizeEvent(event, {
'name': name
}));
}
});
return events;
return normalizedEvents;
}
}
function normalizeEvent(chromeEvent, data) {
var ph = chromeEvent['ph'];
if (StringWrapper.equals(ph, 'S')) {
ph = 'b';
} else if (StringWrapper.equals(ph, 'F')) {
ph = 'e';
}
var result = {
'pid': chromeEvent['pid'],
'ph': ph,
'cat': 'timeline',
'ts': chromeEvent['ts'] / 1000
};
if (chromeEvent['ph'] === 'X') {
result['dur'] = chromeEvent['dur'] / 1000;
}
StringMapWrapper.forEach(data, (value, prop) => {
result[prop] = value;
});
return result;
}
var _BINDINGS = [
bind(WebDriverExtension).toFactory(
(driver) => new ChromeDriverExtension(driver),

View File

@ -0,0 +1,139 @@
import { bind } from 'angular2/di';
import { ListWrapper } from 'angular2/src/facade/collection';
import {
Json, isPresent, isBlank, RegExpWrapper, StringWrapper
} from 'angular2/src/facade/lang';
import { WebDriverExtension } from '../web_driver_extension';
import { WebDriverAdapter } from '../web_driver_adapter';
import { Promise } from 'angular2/src/facade/async';
export class IOsDriverExtension extends WebDriverExtension {
// TODO(tbosch): use static values when our transpiler supports them
static get BINDINGS() { return _BINDINGS; }
_driver:WebDriverAdapter;
constructor(driver:WebDriverAdapter) {
super();
this._driver = driver;
}
gc() {
return this._driver.executeScript('window.gc()');
}
timeBegin(name:string):Promise {
return this._driver.executeScript(`console.time('${name}');`);
}
timeEnd(name:string, restartName:string = null):Promise {
var script = `console.timeEnd('${name}');`;
if (isPresent(restartName)) {
script += `console.time('${restartName}');`
}
return this._driver.executeScript(script);
}
readPerfLog() {
// TODO(tbosch): Bug in IOsDriver: Need to execute at least one command
// so that the browser logs can be read out!
return this._driver.executeScript('1+1')
.then( (_) => this._driver.logs('performance') )
.then( (entries) => {
var records = [];
ListWrapper.forEach(entries, function(entry) {
var message = Json.parse(entry['message'])['message'];
if (StringWrapper.equals(message['method'], 'Timeline.eventRecorded')) {
ListWrapper.push(records, message['params']['record']);
}
});
return this._convertPerfRecordsToEvents(records);
});
}
_convertPerfRecordsToEvents(records, events = null) {
if (isBlank(events)) {
events = [];
}
records.forEach( (record) => {
var endEvent = null;
var type = record['type'];
var data = record['data'];
var startTime = record['startTime'];
var endTime = record['endTime'];
if (StringWrapper.equals(type, 'FunctionCall') &&
(isBlank(data) || !StringWrapper.equals(data['scriptName'], 'InjectedScript'))) {
ListWrapper.push(events, createStartEvent('script', startTime));
endEvent = createEndEvent('script', endTime);
} else if (StringWrapper.equals(type, 'Time')) {
ListWrapper.push(events, createMarkStartEvent(data['message'], startTime));
} else if (StringWrapper.equals(type, 'TimeEnd')) {
ListWrapper.push(events, createMarkEndEvent(data['message'], startTime));
} else if (StringWrapper.equals(type, 'RecalculateStyles') ||
StringWrapper.equals(type, 'Layout') ||
StringWrapper.equals(type, 'UpdateLayerTree') ||
StringWrapper.equals(type, 'Paint') ||
StringWrapper.equals(type, 'Rasterize') ||
StringWrapper.equals(type, 'CompositeLayers')) {
ListWrapper.push(events, createStartEvent('render', startTime));
endEvent = createEndEvent('render', endTime);
} else if (StringWrapper.equals(type, 'GCEvent')) {
ListWrapper.push(events, createStartEvent('gc', startTime, {
'usedHeapSize': 0
}));
endEvent = createEndEvent('gc', endTime, {
'usedHeapSize': -data['usedHeapSizeDelta']
});
}
if (isPresent(record['children'])) {
this._convertPerfRecordsToEvents(record['children'], events);
}
if (isPresent(endEvent)) {
ListWrapper.push(events, endEvent);
}
});
return events;
}
}
function createEvent(ph, name, time, args = null) {
var result = {
'cat': 'timeline',
'name': name,
'ts': time,
'ph': ph,
// The ios protocol does not support the notions of multiple processes in
// the perflog...
'pid': 'pid0'
};
if (isPresent(args)) {
result['args'] = args;
}
return result;
}
function createStartEvent(name, time, args = null) {
return createEvent('B', name, time, args);
}
function createEndEvent(name, time, args = null) {
return createEvent('E', name, time, args);
}
function createMarkStartEvent(name, time) {
return createEvent('b', name, time);
}
function createMarkEndEvent(name, time) {
return createEvent('e', name, time);
}
var _BINDINGS = [
bind(WebDriverExtension).toFactory(
(driver) => new IOsDriverExtension(driver),
[WebDriverAdapter]
)
];

View File

@ -5,8 +5,11 @@ import { PromiseWrapper, Promise } from 'angular2/src/facade/async';
import { Metric, PerflogMetric, WebDriverExtension, bind, Injector } from 'benchpress/benchpress';
import { TraceEventFactory } from '../trace_event_factory';
export function main() {
var commandLog;
var eventFactory = new TraceEventFactory('timeline', 'pid0');
function createMetric(perfLogs) {
commandLog = [];
@ -44,10 +47,10 @@ export function main() {
it('should mark and aggregate events in between the marks', (done) => {
var events = [
[
markStartEvent('benchpress0'),
startEvent('script', 4),
endEvent('script', 6),
markEndEvent('benchpress0')
eventFactory.markStart('benchpress0', 0),
eventFactory.start('script', 4),
eventFactory.end('script', 6),
eventFactory.markEnd('benchpress0', 10)
]
];
var metric = createMetric(events);
@ -68,11 +71,11 @@ export function main() {
it('should restart timing', (done) => {
var events = [
[
markStartEvent('benchpress0'),
markEndEvent('benchpress0'),
markStartEvent('benchpress1'),
eventFactory.markStart('benchpress0', 0),
eventFactory.markEnd('benchpress0', 1),
eventFactory.markStart('benchpress1', 2),
], [
markEndEvent('benchpress1')
eventFactory.markEnd('benchpress1', 3)
]
];
var metric = createMetric(events);
@ -94,9 +97,9 @@ export function main() {
it('should loop and aggregate until the end mark is present', (done) => {
var events = [
[ markStartEvent('benchpress0'), startEvent('script', 1) ],
[ endEvent('script', 2) ],
[ startEvent('script', 3), endEvent('script', 5), markEndEvent('benchpress0') ]
[ 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()
@ -119,9 +122,9 @@ export function main() {
it('should store events after the end mark for the next call', (done) => {
var events = [
[ markStartEvent('benchpress0'), markEndEvent('benchpress0'), markStartEvent('benchpress1'),
startEvent('script', 1), endEvent('script', 2) ],
[ startEvent('script', 3), endEvent('script', 5), markEndEvent('benchpress1') ]
[ 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()
@ -149,8 +152,8 @@ export function main() {
describe('aggregation', () => {
function aggregate(events) {
ListWrapper.insert(events, 0, markStartEvent('benchpress0'));
ListWrapper.push(events, markEndEvent('benchpress0'));
ListWrapper.insert(events, 0, eventFactory.markStart('benchpress0', 0));
ListWrapper.push(events, eventFactory.markEnd('benchpress0', 10));
var metric = createMetric([events]);
return metric
.beginMeasure().then( (_) => metric.endMeasure(false) );
@ -159,8 +162,8 @@ export function main() {
it('should report a single interval', (done) => {
aggregate([
startEvent('script', 0),
endEvent('script', 5)
eventFactory.start('script', 0),
eventFactory.end('script', 5)
]).then((data) => {
expect(data['script']).toBe(5);
done();
@ -169,10 +172,10 @@ export function main() {
it('should sum up multiple intervals', (done) => {
aggregate([
startEvent('script', 0),
endEvent('script', 5),
startEvent('script', 10),
endEvent('script', 17)
eventFactory.start('script', 0),
eventFactory.end('script', 5),
eventFactory.start('script', 10),
eventFactory.end('script', 17)
]).then((data) => {
expect(data['script']).toBe(12);
done();
@ -181,7 +184,7 @@ export function main() {
it('should ignore not started intervals', (done) => {
aggregate([
endEvent('script', 10)
eventFactory.end('script', 10)
]).then((data) => {
expect(data['script']).toBe(0);
done();
@ -190,18 +193,36 @@ export function main() {
it('should ignore not ended intervals', (done) => {
aggregate([
startEvent('script', 10)
eventFactory.start('script', 10)
]).then((data) => {
expect(data['script']).toBe(0);
done();
});
});
it('should ignore events from different processed as the start mark', (done) => {
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['script']).toBe(5);
done();
});
});
['script', 'gcTime', 'render'].forEach( (metricName) => {
it(`should support ${metricName} metric`, (done) => {
aggregate([
startEvent(metricName, 0),
endEvent(metricName, 5)
eventFactory.start(metricName, 0),
eventFactory.end(metricName, 5)
]).then((data) => {
expect(data[metricName]).toBe(5);
done();
@ -211,20 +232,20 @@ export function main() {
it('should support gcAmount metric', (done) => {
aggregate([
startEvent('gc', 0),
endEvent('gc', 5, {'amount': 10})
eventFactory.start('gc', 0, {'usedHeapSize': 2500}),
eventFactory.end('gc', 5, {'usedHeapSize': 1000})
]).then((data) => {
expect(data['gcAmount']).toBe(10);
expect(data['gcAmount']).toBe(1.5);
done();
});
});
it('should subtract gcTime in script from script time', (done) => {
aggregate([
startEvent('script', 0),
startEvent('gc', 1),
endEvent('gc', 4, {'amount': 10}),
endEvent('script', 5)
eventFactory.start('script', 0),
eventFactory.start('gc', 1, {'usedHeapSize': 1000}),
eventFactory.end('gc', 4, {'usedHeapSize': 0}),
eventFactory.end('script', 5)
]).then((data) => {
expect(data['script']).toBe(2);
done();
@ -233,28 +254,40 @@ export function main() {
describe('gcTimeInScript / gcAmountInScript', () => {
it('should use gc during script execution', (done) => {
it('should detect gc during script execution with begin/end events', (done) => {
aggregate([
startEvent('script', 0),
startEvent('gc', 1),
endEvent('gc', 4, {'amount': 10}),
endEvent('script', 5)
eventFactory.start('script', 0),
eventFactory.start('gc', 1, {'usedHeapSize': 10000}),
eventFactory.end('gc', 4, {'usedHeapSize': 0}),
eventFactory.end('script', 5)
]).then((data) => {
expect(data['gcTimeInScript']).toBe(3);
expect(data['gcAmountInScript']).toBe(10);
expect(data['gcAmountInScript']).toBe(10.0);
done();
});
});
it('should detect gc during script execution with complete events', (done) => {
aggregate([
eventFactory.complete('script', 0, 5),
eventFactory.start('gc', 1, {'usedHeapSize': 10000}),
eventFactory.end('gc', 4, {'usedHeapSize': 0})
]).then((data) => {
expect(data['gcTimeInScript']).toBe(3);
expect(data['gcAmountInScript']).toBe(10.0);
done();
});
});
it('should ignore gc outside of script execution', (done) => {
aggregate([
startEvent('gc', 1),
endEvent('gc', 4, {'amount': 10}),
startEvent('script', 0),
endEvent('script', 5)
eventFactory.start('gc', 1, {'usedHeapSize': 10}),
eventFactory.end('gc', 4, {'usedHeapSize': 0}),
eventFactory.start('script', 0),
eventFactory.end('script', 5)
]).then((data) => {
expect(data['gcTimeInScript']).toBe(0);
expect(data['gcAmountInScript']).toBe(0);
expect(data['gcTimeInScript']).toEqual(0.0);
expect(data['gcAmountInScript']).toEqual(0.0);
done();
});
});
@ -266,37 +299,6 @@ export function main() {
});
}
function markStartEvent(type) {
return {
'name': type,
'ph': 'b'
}
}
function markEndEvent(type) {
return {
'name': type,
'ph': 'e'
}
}
function startEvent(type, time) {
return {
'name': type,
'ts': time,
'ph': 'B'
}
}
function endEvent(type, time, args = null) {
return {
'name': type,
'ts': time,
'ph': 'E',
'args': args
}
}
class MockDriverExtension extends WebDriverExtension {
_perfLogs:List;
_commandLog:List;

View File

@ -148,7 +148,6 @@ export function main() {
});
it('should not gc if the flag is not set', (done) => {
var workCount = 0;
var log = [];
createSampler({
metric: createCountingMetric(),

View File

@ -0,0 +1,47 @@
import { isPresent } from 'angular2/src/facade/lang';
export class TraceEventFactory {
_cat:string;
_pid;
constructor(cat, pid) {
this._cat = cat;
this._pid = pid;
}
create(ph, name, time, args = null) {
var res = {
'name': name,
'cat': this._cat,
'ph': ph,
'ts': time,
'pid': this._pid
};
if (isPresent(args)) {
res['args'] = args;
}
return res;
}
markStart(name, time) {
return this.create('b', name, time);
}
markEnd(name, time) {
return this.create('e', name, time);
}
start(name, time, args = null) {
return this.create('B', name, time, args);
}
end(name, time, args = null) {
return this.create('E', name, time, args);
}
complete(name, time, duration, args = null) {
var res = this.create('X', name, time, args);
res['dur'] = duration;
return res;
}
}

View File

@ -2,18 +2,24 @@ import {describe, it, iit, xit, expect, beforeEach, afterEach} from 'angular2/te
import { ListWrapper } from 'angular2/src/facade/collection';
import { PromiseWrapper } from 'angular2/src/facade/async';
import { Json, perfRecords, isBlank } from 'angular2/src/facade/lang';
import { Json, isBlank } from 'angular2/src/facade/lang';
import {
WebDriverExtension, ChromeDriverExtension,
WebDriverAdapter, Injector, bind
} from 'benchpress/benchpress';
import { TraceEventFactory } from '../trace_event_factory';
export function main() {
describe('chrome driver extension', () => {
var log;
var extension;
var blinkEvents = new TraceEventFactory('blink.console', 'pid0');
var chromeTimelineEvents = new TraceEventFactory('disabled-by-default-devtools.timeline', 'pid0');
var normEvents = new TraceEventFactory('timeline', 'pid0');
function createExtension(perfRecords = null) {
if (isBlank(perfRecords)) {
perfRecords = [];
@ -33,23 +39,23 @@ export function main() {
});
});
it('should mark the timeline via console.timeStamp()', (done) => {
it('should mark the timeline via console.time()', (done) => {
createExtension().timeBegin('someName').then( (_) => {
expect(log).toEqual([['executeScript', `console.timeStamp('begin_someName');`]]);
expect(log).toEqual([['executeScript', `console.time('someName');`]]);
done();
});
});
it('should mark the timeline via console.timeEnd()', (done) => {
createExtension().timeEnd('someName').then( (_) => {
expect(log).toEqual([['executeScript', `console.timeStamp('end_someName');`]]);
expect(log).toEqual([['executeScript', `console.timeEnd('someName');`]]);
done();
});
});
it('should mark the timeline via console.time() and console.timeEnd()', (done) => {
createExtension().timeEnd('name1', 'name2').then( (_) => {
expect(log).toEqual([['executeScript', `console.timeStamp('end_name1');console.timeStamp('begin_name2');`]]);
expect(log).toEqual([['executeScript', `console.timeEnd('name1');console.time('name2');`]]);
done();
});
});
@ -66,13 +72,23 @@ export function main() {
});
});
it('should report FunctionCall records as "script"', (done) => {
it('should normalize times to ms and forward ph and pid event properties', (done) => {
createExtension([
durationRecord('FunctionCall', 1, 5)
chromeTimelineEvents.complete('FunctionCall', 1100, 5500, null)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
startEvent('script', 1),
endEvent('script', 5)
normEvents.complete('script', 1.1, 5.5, null),
]);
done();
});
});
it('should report FunctionCall events as "script"', (done) => {
createExtension([
chromeTimelineEvents.start('FunctionCall', 0)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.start('script', 0),
]);
done();
});
@ -80,7 +96,7 @@ export function main() {
it('should ignore FunctionCalls from webdriver', (done) => {
createExtension([
internalScriptRecord(1, 5)
chromeTimelineEvents.start('FunctionCall', 0, {'data': {'scriptName': 'InjectedScript'}})
]).readPerfLog().then( (events) => {
expect(events).toEqual([]);
done();
@ -89,10 +105,10 @@ export function main() {
it('should report begin timestamps', (done) => {
createExtension([
timeStampRecord('begin_someName')
blinkEvents.create('S', 'someName', 1000)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
markStartEvent('someName')
normEvents.markStart('someName', 1.0)
]);
done();
});
@ -100,10 +116,10 @@ export function main() {
it('should report end timestamps', (done) => {
createExtension([
timeStampRecord('end_someName')
blinkEvents.create('F', 'someName', 1000)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
markEndEvent('someName')
normEvents.markEnd('someName', 1.0)
]);
done();
});
@ -111,132 +127,44 @@ export function main() {
it('should report gc', (done) => {
createExtension([
gcRecord(1, 3, 21)
chromeTimelineEvents.start('GCEvent', 1000, {'usedHeapSizeBefore': 1000}),
chromeTimelineEvents.end('GCEvent', 2000, {'usedHeapSizeAfter': 0}),
]).readPerfLog().then( (events) => {
expect(events).toEqual([
startEvent('gc', 1),
endEvent('gc', 3, {'amount': 21}),
normEvents.start('gc', 1.0, {'usedHeapSize': 1000}),
normEvents.end('gc', 2.0, {'usedHeapSize': 0}),
]);
done();
});
});
['RecalculateStyles', 'Layout', 'UpdateLayerTree', 'Paint', 'Rasterize', 'CompositeLayers'].forEach( (recordType) => {
it(`should report ${recordType}`, (done) => {
it(`should report ${recordType} as "render"`, (done) => {
createExtension([
durationRecord(recordType, 0, 1)
chromeTimelineEvents.start(recordType, 1234),
chromeTimelineEvents.end(recordType, 2345)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
startEvent('render', 0),
endEvent('render', 1),
normEvents.start('render', 1.234),
normEvents.end('render', 2.345),
]);
done();
});
});
});
it('should walk children', (done) => {
createExtension([
durationRecord('FunctionCall', 1, 5, [
timeStampRecord('begin_someName')
])
]).readPerfLog().then( (events) => {
expect(events).toEqual([
startEvent('script', 1),
markStartEvent('someName'),
endEvent('script', 5)
]);
done();
});
});
});
});
}
function timeStampRecord(name) {
return {
'type': 'TimeStamp',
'data': {
'message': name
}
};
}
function durationRecord(type, startTime, endTime, children = null) {
if (isBlank(children)) {
children = [];
}
return {
'type': type,
'startTime': startTime,
'endTime': endTime,
'children': children
};
}
function internalScriptRecord(startTime, endTime) {
return {
'type': 'FunctionCall',
'startTime': startTime,
'endTime': endTime,
'data': {
'scriptName': 'InjectedScript'
}
};
}
function gcRecord(startTime, endTime, gcAmount) {
return {
'type': 'GCEvent',
'startTime': startTime,
'endTime': endTime,
'data': {
'usedHeapSizeDelta': gcAmount
}
};
}
function markStartEvent(type) {
return {
'name': type,
'ph': 'b'
}
}
function markEndEvent(type) {
return {
'name': type,
'ph': 'e'
}
}
function startEvent(type, time) {
return {
'name': type,
'ts': time,
'ph': 'B'
}
}
function endEvent(type, time, args = null) {
return {
'name': type,
'ts': time,
'ph': 'E',
'args': args
}
}
class MockDriverAdapter extends WebDriverAdapter {
_log:List;
_perfRecords:List;
constructor(log, perfRecords) {
_events:List;
constructor(log, events) {
super();
this._log = log;
this._perfRecords = perfRecords;
this._events = events;
}
executeScript(script) {
@ -247,14 +175,12 @@ class MockDriverAdapter extends WebDriverAdapter {
logs(type) {
ListWrapper.push(this._log, ['logs', type]);
if (type === 'performance') {
return PromiseWrapper.resolve(this._perfRecords.map(function(record) {
return PromiseWrapper.resolve(this._events.map(function(event) {
return {
'message': Json.stringify({
'message': {
'method': 'Timeline.eventRecorded',
'params': {
'record': record
}
'method': 'Tracing.dataCollected',
'params': event
}
})
};

View File

@ -0,0 +1,251 @@
import {describe, ddescribe, it, iit, xit, expect, beforeEach, afterEach} from 'angular2/test_lib';
import { ListWrapper } from 'angular2/src/facade/collection';
import { PromiseWrapper } from 'angular2/src/facade/async';
import { Json, isBlank, isPresent } from 'angular2/src/facade/lang';
import {
WebDriverExtension, IOsDriverExtension,
WebDriverAdapter, Injector, bind
} from 'benchpress/benchpress';
import { TraceEventFactory } from '../trace_event_factory';
export function main() {
describe('ios driver extension', () => {
var log;
var extension;
var normEvents = new TraceEventFactory('timeline', 'pid0');
function createExtension(perfRecords = null) {
if (isBlank(perfRecords)) {
perfRecords = [];
}
log = [];
extension = new Injector([
IOsDriverExtension.BINDINGS,
bind(WebDriverAdapter).toValue(new MockDriverAdapter(log, perfRecords))
]).get(WebDriverExtension);
return extension;
}
it('should force gc via window.gc()', (done) => {
createExtension().gc().then( (_) => {
expect(log).toEqual([['executeScript', 'window.gc()']]);
done();
});
});
it('should mark the timeline via console.time()', (done) => {
createExtension().timeBegin('someName').then( (_) => {
expect(log).toEqual([['executeScript', `console.time('someName');`]]);
done();
});
});
it('should mark the timeline via console.timeEnd()', (done) => {
createExtension().timeEnd('someName').then( (_) => {
expect(log).toEqual([['executeScript', `console.timeEnd('someName');`]]);
done();
});
});
it('should mark the timeline via console.time() and console.timeEnd()', (done) => {
createExtension().timeEnd('name1', 'name2').then( (_) => {
expect(log).toEqual([['executeScript', `console.timeEnd('name1');console.time('name2');`]]);
done();
});
});
describe('readPerfLog', () => {
it('should execute a dummy script before reading them', (done) => {
// TODO(tbosch): This seems to be a bug in ChromeDriver:
// Sometimes it does not report the newest events of the performance log
// to the WebDriver client unless a script is executed...
createExtension([]).readPerfLog().then( (_) => {
expect(log).toEqual([ [ 'executeScript', '1+1' ], [ 'logs', 'performance' ] ]);
done();
});
});
it('should report FunctionCall records as "script"', (done) => {
createExtension([
durationRecord('FunctionCall', 1, 5)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.start('script', 1),
normEvents.end('script', 5)
]);
done();
});
});
it('should ignore FunctionCalls from webdriver', (done) => {
createExtension([
internalScriptRecord(1, 5)
]).readPerfLog().then( (events) => {
expect(events).toEqual([]);
done();
});
});
it('should report begin time', (done) => {
createExtension([
timeBeginRecord('someName', 12)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.markStart('someName', 12)
]);
done();
});
});
it('should report end timestamps', (done) => {
createExtension([
timeEndRecord('someName', 12)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.markEnd('someName', 12)
]);
done();
});
});
it('should report gc', (done) => {
createExtension([
gcRecord(1, 3, 21)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.start('gc', 1, {'usedHeapSize': 0}),
normEvents.end('gc', 3, {'usedHeapSize': -21}),
]);
done();
});
});
['RecalculateStyles', 'Layout', 'UpdateLayerTree', 'Paint', 'Rasterize', 'CompositeLayers'].forEach( (recordType) => {
it(`should report ${recordType}`, (done) => {
createExtension([
durationRecord(recordType, 0, 1)
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.start('render', 0),
normEvents.end('render', 1),
]);
done();
});
});
});
it('should walk children', (done) => {
createExtension([
durationRecord('FunctionCall', 1, 5, [
timeBeginRecord('someName', 2)
])
]).readPerfLog().then( (events) => {
expect(events).toEqual([
normEvents.start('script', 1),
normEvents.markStart('someName', 2),
normEvents.end('script', 5)
]);
done();
});
});
});
});
}
function timeBeginRecord(name, time) {
return {
'type': 'Time',
'startTime': time,
'data': {
'message': name
}
};
}
function timeEndRecord(name, time) {
return {
'type': 'TimeEnd',
'startTime': time,
'data': {
'message': name
}
};
}
function durationRecord(type, startTime, endTime, children = null) {
if (isBlank(children)) {
children = [];
}
return {
'type': type,
'startTime': startTime,
'endTime': endTime,
'children': children
};
}
function internalScriptRecord(startTime, endTime) {
return {
'type': 'FunctionCall',
'startTime': startTime,
'endTime': endTime,
'data': {
'scriptName': 'InjectedScript'
}
};
}
function gcRecord(startTime, endTime, gcAmount) {
return {
'type': 'GCEvent',
'startTime': startTime,
'endTime': endTime,
'data': {
'usedHeapSizeDelta': gcAmount
}
};
}
class MockDriverAdapter extends WebDriverAdapter {
_log:List;
_perfRecords:List;
constructor(log, perfRecords) {
super();
this._log = log;
this._perfRecords = perfRecords;
}
executeScript(script) {
ListWrapper.push(this._log, ['executeScript', script]);
return PromiseWrapper.resolve(null);
}
logs(type) {
ListWrapper.push(this._log, ['logs', type]);
if (type === 'performance') {
return PromiseWrapper.resolve(this._perfRecords.map(function(record) {
return {
'message': Json.stringify({
'message': {
'method': 'Timeline.eventRecorded',
'params': {
'record': record
}
}
})
};
}));
} else {
return null;
}
}
}

View File

@ -35,7 +35,10 @@ var BROWSER_CAPS = {
browserName: 'chrome',
chromeOptions: {
'binary': process.env.DARTIUM,
'args': ['--js-flags=--expose-gc']
'args': ['--js-flags=--expose-gc'],
'perfLoggingPrefs': {
'traceCategories': 'blink.console,disabled-by-default-devtools.timeline'
}
},
loggingPrefs: {
performance: 'ALL',
@ -45,7 +48,10 @@ var BROWSER_CAPS = {
ChromeDesktop: {
browserName: 'chrome',
chromeOptions: {
'args': ['--js-flags=--expose-gc']
'args': ['--js-flags=--expose-gc'],
'perfLoggingPrefs': {
'traceCategories': 'blink.console,disabled-by-default-devtools.timeline'
}
},
loggingPrefs: {
performance: 'ALL',
@ -56,12 +62,36 @@ var BROWSER_CAPS = {
browserName: 'chrome',
chromeOptions: {
androidPackage: 'com.android.chrome',
'args': ['--js-flags=--expose-gc']
'args': ['--js-flags=--expose-gc'],
'perfLoggingPrefs': {
'traceCategories': 'blink.console,disabled-by-default-devtools.timeline'
}
},
loggingPrefs: {
performance: 'ALL',
browser: 'ALL'
}
},
IPhoneSimulator: {
browserName: 'MobileSafari',
simulator: true,
CFBundleName: 'Safari',
device: 'iphone',
instruments: 'true',
loggingPrefs: {
performance: 'ALL',
browser: 'ALL'
}
},
IPadNative: {
browserName: 'MobileSafari',
simulator: false,
CFBundleName: 'Safari',
device: 'ipad',
loggingPrefs: {
performance: 'ALL',
browser: 'ALL'
}
}
};
@ -145,7 +175,13 @@ exports.createBenchpressRunner = function(options) {
benchpress.bind(benchpress.Options.DEFAULT_DESCRIPTION).toValue({
'lang': options.lang,
'runId': runId
})
}),
// TODO(tbosch): Make the ChromeDriverExtension configurable based on the
// capabilities. Should support the case where we test against
// ios and chrome at the same time!
benchpress.bind(benchpress.WebDriverExtension).toFactory(function(adapter) {
return new benchpress.ChromeDriverExtension(adapter);
}, [benchpress.WebDriverAdapter])
];
if (argv['benchmark']) {
bindings.push(benchpress.RegressionSlopeValidator.BINDINGS);

View File

@ -51,7 +51,7 @@ function filterByFile(pathMapping, folder) {
function insertSrcFolder(plugins, srcFolderInsertion) {
return plugins.rename(function(file) {
var folder = file.dirname;
var srcDir = filterByFile(srcFolderInsertion, folder);
var srcDir = filterByFile(srcFolderInsertion, path.join(folder, file.basename));
if (srcDir) {
var folderParts = file.dirname.split(path.sep);
folder = [folderParts[0], srcDir].concat(folderParts.slice(1)).join(path.sep);