From 7aa031b3d34b791e6033c9dd135dfcef6cbf092c Mon Sep 17 00:00:00 2001 From: Tobias Bosch Date: Wed, 18 Feb 2015 14:39:52 -0800 Subject: [PATCH] feat(bench press): use chrome tracing protocol and initial iOS support --- modules/angular2/src/facade/collection.dart | 3 + modules/angular2/src/facade/collection.es6 | 4 + modules/benchpress/benchpress.js | 1 + .../benchpress/src/metric/perflog_metric.js | 81 +++--- .../benchpress/src/web_driver_extension.js | 14 +- .../src/webdriver/chrome_driver_extension.js | 160 +++++------ .../src/webdriver/ios_driver_extension.js | 139 ++++++++++ .../test/metric/perflog_metric_spec.js | 154 +++++------ modules/benchpress/test/sampler_spec.js | 1 - .../benchpress/test/trace_event_factory.js | 47 ++++ .../webdriver/chrome_driver_extension_spec.js | 164 ++++-------- .../webdriver/ios_driver_extension_spec.js | 251 ++++++++++++++++++ protractor-shared.js | 44 ++- tools/build/util.js | 2 +- 14 files changed, 733 insertions(+), 332 deletions(-) create mode 100644 modules/benchpress/src/webdriver/ios_driver_extension.js create mode 100644 modules/benchpress/test/trace_event_factory.js create mode 100644 modules/benchpress/test/webdriver/ios_driver_extension_spec.js diff --git a/modules/angular2/src/facade/collection.dart b/modules/angular2/src/facade/collection.dart index 928f8ea6e2..629078294e 100644 --- a/modules/angular2/src/facade/collection.dart +++ b/modules/angular2/src/facade/collection.dart @@ -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; diff --git a/modules/angular2/src/facade/collection.es6 b/modules/angular2/src/facade/collection.es6 index 763335cf6c..c6d3319eb6 100644 --- a/modules/angular2/src/facade/collection.es6 +++ b/modules/angular2/src/facade/collection.es6 @@ -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 { diff --git a/modules/benchpress/benchpress.js b/modules/benchpress/benchpress.js index d2c372d666..d60603da35 100644 --- a/modules/benchpress/benchpress.js +++ b/modules/benchpress/benchpress.js @@ -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'; diff --git a/modules/benchpress/src/metric/perflog_metric.js b/modules/benchpress/src/metric/perflog_metric.js index 7fe1326124..da18a71d56 100644 --- a/modules/benchpress/src/metric/perflog_metric.js +++ b/modules/benchpress/src/metric/perflog_metric.js @@ -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) { diff --git a/modules/benchpress/src/web_driver_extension.js b/modules/benchpress/src/web_driver_extension.js index 99e7ff19ca..79468c211b 100644 --- a/modules/benchpress/src/web_driver_extension.js +++ b/modules/benchpress/src/web_driver_extension.js @@ -13,10 +13,6 @@ export class WebDriverExtension { throw new BaseException('NYI'); } - timeStamp(name:string, names:List):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) **/ diff --git a/modules/benchpress/src/webdriver/chrome_driver_extension.js b/modules/benchpress/src/webdriver/chrome_driver_extension.js index aba3021dce..3a361fc478 100644 --- a/modules/benchpress/src/webdriver/chrome_driver_extension.js +++ b/modules/benchpress/src/webdriver/chrome_driver_extension.js @@ -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), diff --git a/modules/benchpress/src/webdriver/ios_driver_extension.js b/modules/benchpress/src/webdriver/ios_driver_extension.js new file mode 100644 index 0000000000..48220c58a2 --- /dev/null +++ b/modules/benchpress/src/webdriver/ios_driver_extension.js @@ -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] + ) +]; \ No newline at end of file diff --git a/modules/benchpress/test/metric/perflog_metric_spec.js b/modules/benchpress/test/metric/perflog_metric_spec.js index dca4ea67e0..37d1696b29 100644 --- a/modules/benchpress/test/metric/perflog_metric_spec.js +++ b/modules/benchpress/test/metric/perflog_metric_spec.js @@ -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; diff --git a/modules/benchpress/test/sampler_spec.js b/modules/benchpress/test/sampler_spec.js index 8459b691e9..caa33d24b1 100644 --- a/modules/benchpress/test/sampler_spec.js +++ b/modules/benchpress/test/sampler_spec.js @@ -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(), diff --git a/modules/benchpress/test/trace_event_factory.js b/modules/benchpress/test/trace_event_factory.js new file mode 100644 index 0000000000..4876ebbe94 --- /dev/null +++ b/modules/benchpress/test/trace_event_factory.js @@ -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; + } +} \ No newline at end of file diff --git a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js index f722b3d1de..061e696c99 100644 --- a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js +++ b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js @@ -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 } }) }; diff --git a/modules/benchpress/test/webdriver/ios_driver_extension_spec.js b/modules/benchpress/test/webdriver/ios_driver_extension_spec.js new file mode 100644 index 0000000000..a6bd8b52f0 --- /dev/null +++ b/modules/benchpress/test/webdriver/ios_driver_extension_spec.js @@ -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; + } + } + +} diff --git a/protractor-shared.js b/protractor-shared.js index 54b07fd57c..73856b8b6d 100644 --- a/protractor-shared.js +++ b/protractor-shared.js @@ -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); diff --git a/tools/build/util.js b/tools/build/util.js index c5d840c172..a1f60650c3 100644 --- a/tools/build/util.js +++ b/tools/build/util.js @@ -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);