From 6f303121c673d1baaed4b2ffb1902ec7404f9846 Mon Sep 17 00:00:00 2001 From: Tobias Bosch Date: Mon, 29 Dec 2014 15:36:29 -0800 Subject: [PATCH] refactor(perf): introduce benchpress2 Major changes: - make API more reusable - format output nicely - only force gc if needed Regarding forcing gc: Forcing gc can change script execution time. We now don't force gc at first and ignore results where gc happens during script execution. When we ignored too many results, we switch to forcing gc. Closes #339 --- .../test/perf/change_detection_perf.js | 30 ++- modules/benchmarks/test/perf/compiler_perf.js | 30 ++- modules/benchmarks/test/perf/di_perf.js | 38 ++- .../test/perf/element_injector_perf.js | 30 ++- modules/benchmarks/test/perf/tree_perf.js | 30 ++- .../test/perf/compiler_perf.js | 31 ++- .../test/perf/tree_perf.js | 26 +- package.json | 3 +- protractor-perf-shared.js | 16 +- tools/benchpress/benchpress.js | 7 + tools/benchpress/commands.js | 55 +++++ tools/benchpress/reporter.js | 32 +++ tools/benchpress/stats.js | 52 ++++ tools/benchpress/time_benchmark.js | 227 +++++++++++++++++ tools/benchpress/tools.js | 18 ++ tools/perf/util.js | 232 ------------------ 16 files changed, 572 insertions(+), 285 deletions(-) create mode 100644 tools/benchpress/benchpress.js create mode 100644 tools/benchpress/commands.js create mode 100644 tools/benchpress/reporter.js create mode 100644 tools/benchpress/stats.js create mode 100644 tools/benchpress/time_benchmark.js create mode 100644 tools/benchpress/tools.js delete mode 100644 tools/perf/util.js diff --git a/modules/benchmarks/test/perf/change_detection_perf.js b/modules/benchmarks/test/perf/change_detection_perf.js index 256453460e..315b02dc6c 100644 --- a/modules/benchmarks/test/perf/change_detection_perf.js +++ b/modules/benchmarks/test/perf/change_detection_perf.js @@ -1,26 +1,44 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng2 change detection benchmark', function () { var URL = 'benchmarks/web/change_detection/change_detection_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log ng stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#ng2DetectChanges'], - name: browser.params.lang+'.ng2.changeDetection' + logId: 'ng2.changeDetection' }); }); it('should log baseline stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#baselineDetectChanges'], - name: browser.params.lang+'.baseline.changeDetection' + logId: 'baseline.changeDetection' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/modules/benchmarks/test/perf/compiler_perf.js b/modules/benchmarks/test/perf/compiler_perf.js index 7aab743ca1..f3e5da3113 100644 --- a/modules/benchmarks/test/perf/compiler_perf.js +++ b/modules/benchmarks/test/perf/compiler_perf.js @@ -1,26 +1,44 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng2 compiler benchmark', function () { var URL = 'benchmarks/web/compiler/compiler_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log withBindings stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#compileWithBindings'], - name: browser.params.lang+'.ng2.compile.withBindings' + logId: 'ng2.compile.withBindings' }); }); it('should log noBindings stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#compileNoBindings'], - name: browser.params.lang+'.ng2.compile.noBindings' + logId: 'ng2.compile.noBindings' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/modules/benchmarks/test/perf/di_perf.js b/modules/benchmarks/test/perf/di_perf.js index a25ada02d4..cb289d4a0e 100644 --- a/modules/benchmarks/test/perf/di_perf.js +++ b/modules/benchmarks/test/perf/di_perf.js @@ -1,42 +1,60 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng2 di benchmark', function () { var URL = 'benchmarks/web/di/di_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log the stats for getByToken', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#getByToken'], - name: browser.params.lang+'.ng2.di.getByToken' + logId: 'ng2.di.getByToken' }); }); it('should log the stats for getByKey', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#getByKey'], - name: browser.params.lang+'.ng2.di.getByKey' + logId: 'ng2.di.getByKey' }); }); it('should log the stats for getChild', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#getChild'], - name: browser.params.lang+'.ng2.di.getChild' + logId: 'ng2.di.getChild' }); }); it('should log the stats for instantiate', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#instantiate'], - name: browser.params.lang+'.ng2.di.instantiate' + logId: 'ng2.di.instantiate' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/modules/benchmarks/test/perf/element_injector_perf.js b/modules/benchmarks/test/perf/element_injector_perf.js index bdf5ba262d..50a2a017b5 100644 --- a/modules/benchmarks/test/perf/element_injector_perf.js +++ b/modules/benchmarks/test/perf/element_injector_perf.js @@ -1,26 +1,44 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng2 element injector benchmark', function () { var URL = 'benchmarks/web/element_injector/element_injector_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log the stats for instantiate', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#instantiate'], - name: browser.params.lang+'.ng2.elementInjector.instantiate' + logId: 'ng2.elementInjector.instantiate' }); }); it('should log the stats for instantiateDirectives', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#instantiateDirectives'], - name: browser.params.lang+'.ng2.elementInjector.instantiateDirectives' + logId: 'ng2.elementInjector.instantiateDirectives' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/modules/benchmarks/test/perf/tree_perf.js b/modules/benchmarks/test/perf/tree_perf.js index 7dc57e8c9a..2ee6fd5c43 100644 --- a/modules/benchmarks/test/perf/tree_perf.js +++ b/modules/benchmarks/test/perf/tree_perf.js @@ -1,26 +1,44 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng2 tree benchmark', function () { var URL = 'benchmarks/web/tree/tree_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log the ng stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#ng2DestroyDom', '#ng2CreateDom'], - name: browser.params.lang+'.ng2.tree' + logId: 'ng2.tree' }); }); it('should log the baseline stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#baselineDestroyDom', '#baselineCreateDom'], - name: browser.params.lang+'.baseline.tree' + logId: 'baseline.tree' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/modules/benchmarks_external/test/perf/compiler_perf.js b/modules/benchmarks_external/test/perf/compiler_perf.js index a76e328f81..9ce85e385c 100644 --- a/modules/benchmarks_external/test/perf/compiler_perf.js +++ b/modules/benchmarks_external/test/perf/compiler_perf.js @@ -1,25 +1,44 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng1.x compiler benchmark', function () { var URL = 'benchmarks_external/web/compiler/compiler_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log withBinding stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#compileWithBindings'], - name: browser.params.lang+'.ng1.compile.withBindings' + logId: 'ng1.compile.withBindings' }); }); it('should log noBindings stats', function() { - util.runClickBenchmark({ + browser.get(URL); + runClickTimeBenchmark({ buttons: ['#compileNoBindings'], - name: browser.params.lang+'.ng1.compile.noBindings' + logId: 'ng1.compile.noBindings' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/modules/benchmarks_external/test/perf/tree_perf.js b/modules/benchmarks_external/test/perf/tree_perf.js index bafef29a62..7966e5a1dc 100644 --- a/modules/benchmarks_external/test/perf/tree_perf.js +++ b/modules/benchmarks_external/test/perf/tree_perf.js @@ -1,18 +1,36 @@ "use strict"; -var util = require('../../../../tools/perf/util.js'); +var benchpress = require('../../../../tools/benchpress/benchpress.js'); describe('ng1.x tree benchmark', function () { var URL = 'benchmarks_external/web/tree/tree_benchmark.html'; - afterEach(util.verifyNoErrors); + afterEach(benchpress.verifyNoBrowserErrors); it('should log the stats', function() { browser.get(URL); - util.runClickBenchmark({ + runClickTimeBenchmark({ buttons: ['#destroyDom', '#createDom'], - name: browser.params.lang+'.ng1.tree' + logId: 'ng1.tree' }); }); }); + +function runClickTimeBenchmark(config) { + var buttons = config.buttons.map(function(selector) { + return $(selector); + }); + var timeParams = browser.params.timeBenchmark; + benchpress.runTimeBenchmark({ + sampleSize: timeParams.sampleSize, + targetCoefficientOfVariation: timeParams.targetCoefficientOfVariation, + timeout: timeParams.timeout, + metrics: timeParams.metrics, + logId: browser.params.lang+'.'+config.logId + }, function() { + buttons.forEach(function(button) { + button.click(); + }); + }); +} diff --git a/package.json b/package.json index 3ba814508d..ddc660e8ae 100644 --- a/package.json +++ b/package.json @@ -43,6 +43,7 @@ "gulp-webserver": "^0.8.7", "angular": "1.3.5", "minimatch": "^2.0.1", - "lodash": "^2.4.1" + "lodash": "^2.4.1", + "sprintf-js": "1.0.*" } } diff --git a/protractor-perf-shared.js b/protractor-perf-shared.js index 73238e34a3..550a11f2ba 100644 --- a/protractor-perf-shared.js +++ b/protractor-perf-shared.js @@ -3,13 +3,13 @@ var config = exports.config = { specs: ['modules/*/test/**/*_perf.js'], params: { - // size of the sample to take - sampleSize: 10, - // error to be used for early exit - exitOnErrorLowerThan: 4, - // maxium number times the benchmark gets repeated before we output the stats - // of the best sample - maxRepeatCount: 30 + timeBenchmark: { + // size of the sample to take + sampleSize: 10, + targetCoefficientOfVariation: 4, + timeout: 20000, + metrics: ['script', 'render'] + } }, // Disable waiting for Angular as we don't have an integration layer yet... @@ -54,4 +54,4 @@ if (process.env.TRAVIS) { performance: 'ALL' } }; -} \ No newline at end of file +} diff --git a/tools/benchpress/benchpress.js b/tools/benchpress/benchpress.js new file mode 100644 index 0000000000..ef33d0657f --- /dev/null +++ b/tools/benchpress/benchpress.js @@ -0,0 +1,7 @@ +var timeBenchmark = require('./time_benchmark'); +var tools = require('./tools'); + +module.exports = { + runTimeBenchmark: timeBenchmark.runTimeBenchmark, + verifyNoBrowserErrors: tools.verifyNoBrowserErrors +}; \ No newline at end of file diff --git a/tools/benchpress/commands.js b/tools/benchpress/commands.js new file mode 100644 index 0000000000..165da53d52 --- /dev/null +++ b/tools/benchpress/commands.js @@ -0,0 +1,55 @@ +var webdriver = require('protractor/node_modules/selenium-webdriver'); + +module.exports = { + gc: gc, + timelineRecords: timelineRecords, + timelineTimestamp: timelineTimestamp +}; + +function timelineTimestamp(timestampId) { + browser.executeScript('console.timeStamp("'+timestampId+'")'); +} + +function timelineRecords() { + return perfLogs().then(function(logs) { + var logs = logs && logs['Timeline.eventRecorded'] || []; + return logs.map(function(message) { + return message.record; + }); + }); +} + +function perfLogs() { + return plainLogs('performance').then(function(entries) { + var entriesByMethod = {}; + entries.forEach(function(entry) { + var message = JSON.parse(entry.message).message; + var entries = entriesByMethod[message.method]; + if (!entries) { + entries = entriesByMethod[message.method] = []; + } + entries.push(message.params); + }); + return entriesByMethod; + }); +} + +// Needed as selenium-webdriver does not forward +// performance logs in the correct way +function plainLogs(type) { + return browser.driver.schedule( + new webdriver.Command(webdriver.CommandName.GET_LOG). + setParameter('type', type), + 'WebDriver.manage().logs().get(' + type + ')'); +} + +function gc() { + // TODO(tbosch): this only works on chrome, and we actually should + // extend chromedriver to use the Debugger.CollectGarbage call of the + // remote debugger protocol. + // See http://src.chromium.org/viewvc/blink/trunk/Source/devtools/protocol.json + // For iOS Safari we need an extension to appium that uses + // the webkit remote debug protocol. See + // https://github.com/WebKit/webkit/blob/master/Source/WebInspectorUI/Versions/Inspector-iOS-8.0.json + return browser.executeScript('window.gc()'); +} diff --git a/tools/benchpress/reporter.js b/tools/benchpress/reporter.js new file mode 100644 index 0000000000..6503c1c04a --- /dev/null +++ b/tools/benchpress/reporter.js @@ -0,0 +1,32 @@ +var vsprintf = require("sprintf-js").vsprintf; + +var HEADER_SEPARATORS = ['----', '----', '----', '----']; +var FOOTER_SEPARATORS = ['====', '====', '====', '====']; + +module.exports = { + printHeading: printHeading, + printTableHeader: printTableHeader, + printTableFooter: printTableFooter, + printRow: printRow +}; + +function printHeading(title) { + console.log('\n'); + console.log('## '+title); +} + +function printTableHeader(format, values) { + printRow(format, values); + // TODO(tbosch): generate separators dynamically based on the format! + printRow(format, HEADER_SEPARATORS); +} + +function printTableFooter(format, values) { + // TODO(tbosch): generate separators dynamically based on the format! + printRow(format, FOOTER_SEPARATORS); + printRow(format, values); +} + +function printRow(format, values) { + console.log(vsprintf(format, values)); +} \ No newline at end of file diff --git a/tools/benchpress/stats.js b/tools/benchpress/stats.js new file mode 100644 index 0000000000..dab3d581bb --- /dev/null +++ b/tools/benchpress/stats.js @@ -0,0 +1,52 @@ +module.exports = { + createObjectStatsAggregator: createObjectStatsAggregator, + calculateCoefficientOfVariation: calculateCoefficientOfVariation, + calculateMean: calculateMean, + calculateStandardDeviation: calculateStandardDeviation +}; + +function createObjectStatsAggregator(sampleSize) { + var propSamples = {}; + var lastResult; + return addData; + + function addData(data) { + lastResult = {}; + for (var prop in data) { + var samples = propSamples[prop]; + if (!samples) { + samples = propSamples[prop] = []; + } + samples.push(data[prop]); + samples.splice(0, samples.length - sampleSize); + var mean = calculateMean(samples); + lastResult[prop] = { + mean: mean, + coefficientOfVariation: calculateCoefficientOfVariation(samples, mean), + count: samples.length + }; + } + addData.current = lastResult; + return lastResult; + } +} + +function calculateCoefficientOfVariation(sample, mean) { + return calculateStandardDeviation(sample, mean) / mean * 100; +} + +function calculateMean(sample) { + var total = 0; + sample.forEach(function(x) { total += x; }); + return total / sample.length; +} + +function calculateStandardDeviation(sample, mean) { + var deviation = 0; + sample.forEach(function(x) { + deviation += Math.pow(x - mean, 2); + }); + deviation = deviation / (sample.length); + deviation = Math.sqrt(deviation); + return deviation; +} \ No newline at end of file diff --git a/tools/benchpress/time_benchmark.js b/tools/benchpress/time_benchmark.js new file mode 100644 index 0000000000..7153bb6642 --- /dev/null +++ b/tools/benchpress/time_benchmark.js @@ -0,0 +1,227 @@ +var stats = require('./stats'); +var reporter = require('./reporter'); +var commands = require('./commands'); + +var SUPPORTED_METRICS = { + script: true, + gcTime: true, + gcAmount: true, + gcTimeDuringScript: true, + gcAmountDuringScript: true, + gcAmountPerMs: true, + render: true +}; +var DETERMINE_FORCE_GC_MODE_ITERATIONS = 5; + +var MODE_FORCE_GC = 'forceGc'; +var MODE_IGNORE_RUNS_WITH_GC = 'ignoreRunsWithGc'; +var MODE_INDETERMINATE = 'indeterminate'; + +var nextTimestampId = 0; + +module.exports = { + runTimeBenchmark: runTimeBenchmark, + supportedMetrics: SUPPORTED_METRICS +}; + +function runTimeBenchmark(config, workCallback) { + config.metrics.forEach(function(metric) { + if (!(metric in SUPPORTED_METRICS)) { + throw new Error('Metric '+metric+' is not suported by benchpress right now'); + } + }); + var ROW_FORMAT = ['%-40s'].concat(config.metrics.map(function() { + return '%12s'; + })).join(' | '); + + var benchmarkStatsAggregator = stats.createObjectStatsAggregator(config.sampleSize); + + var startTime = Date.now(); + startLoop().then(endLoop); + + var gcDuringScriptCount = 0; + + function startLoop(gcData) { + reporter.printHeading('SCRIPT DATA: sampling size '+config.sampleSize); + reporter.printTableHeader(ROW_FORMAT, ['name'].concat(config.metrics)); + return loop(0, MODE_INDETERMINATE); + } + + function endLoop(stats) { + reporter.printTableFooter(ROW_FORMAT, [config.logId] + .concat(formatObjectStats(stats, config.metrics)) + ); + return config.metrics.map(function(metric) { + return stats[metric]; + }); + } + + function loop(iterationIndex, mode) { + // For fast tests that don't create a lot of garbage, + // we don't want to force gc before every run as that + // can slow down the script execution time (even when we subtract + // the gc time)! + if (mode === MODE_FORCE_GC) { + commands.gc(); + } + return measureTime(workCallback).then(function(benchmarkData) { + var hasGcDuringScript = !!benchmarkData.gcTimeDuringScript; + var ignoreBenchmarkRun = false; + if (hasGcDuringScript) { + gcDuringScriptCount ++; + ignoreBenchmarkRun = (mode === MODE_INDETERMINATE || mode === MODE_IGNORE_RUNS_WITH_GC); + } + if (mode === MODE_INDETERMINATE && iterationIndex >= DETERMINE_FORCE_GC_MODE_ITERATIONS) { + mode = (gcDuringScriptCount / iterationIndex > 0.5) ? MODE_FORCE_GC : MODE_IGNORE_RUNS_WITH_GC; + } + + var rowTitle; + if (ignoreBenchmarkRun) { + rowTitle = '(ignored: gc in script)'; + } else { + rowTitle = config.logId + '#' + iterationIndex; + } + reporter.printRow(ROW_FORMAT, [rowTitle] + .concat(formatObjectData(benchmarkData, config.metrics)) + ); + + var benchmarkStats; + if (!ignoreBenchmarkRun) { + benchmarkStats = benchmarkStatsAggregator(benchmarkData); + } else { + benchmarkStats = benchmarkStatsAggregator.current; + } + + if (Date.now() - startTime > config.timeout) { + return benchmarkStats; + } + if (benchmarkStats && + ( + benchmarkStats.script.count >= config.sampleSize && + benchmarkStats.script.coefficientOfVariation < config.targetCoefficientOfVariation) + ) { + return benchmarkStats + } + return loop(iterationIndex+1, mode); + }); + } +} + + +function formatObjectData(data, props) { + return props.map(function(prop) { + return data[prop].toFixed(2); + }); +} + +function formatObjectStats(stats, props) { + return props.map(function(prop) { + var entry = stats[prop]; + return entry.mean.toFixed(2) + '\u00B1' + entry.coefficientOfVariation.toFixed(2); + }); +} + +function measureTime(callback) { + var startId = (nextTimestampId++).toString(); + var endId = (nextTimestampId++).toString(); + commands.timelineTimestamp(startId); + callback(); + commands.timelineTimestamp(endId); + var allRecords = []; + return readResult(); + + function readResult() { + return commands.timelineRecords().then(function(records) { + allRecords.push.apply(allRecords, records); + var stats = sumTimelineRecords(allRecords, startId, endId); + if (stats.timeStamps.indexOf(startId) === -1 || + stats.timeStamps.indexOf(endId) === -1) { + // Sometimes the logs have not yet arrived at the webdriver + // server from the browser. + // And sometimes, just waiting is not enough, so we + // execute a dummy js function :-( + browser.executeScript('1+1'); + browser.sleep(100); + return readResult(); + } else { + return stats; + } + }); + } +} + +function sumTimelineRecords(records, startTimeStampId, endTimeStampId) { + var isStarted = false; + var recordStats = { + script: 0, + gcTime: 0, + gcAmount: 0, + gcTimeDuringScript: 0, + gcAmountDuringScript: 0, + render: 0, + timeStamps: [] + }; + records.forEach(function(record) { + processRecord(record, recordStats, false); + }); + recordStats.gcAmountPerMs = 0; + if (recordStats.gcAmount) { + recordStats.gcAmountPerMs = recordStats.gcAmount / recordStats.gcTime; + } + return recordStats; + + function processRecord(record, recordStats, parentIsFunctionCall) { + if (record.type === 'TimeStamp' && record.data.message === startTimeStampId) { + isStarted = true; + } + + // ignore scripts that were injected by Webdriver (e.g. calculation of element positions, ...) + var isFunctionCall = record.type === 'FunctionCall' && + (!record.data || record.data.scriptName !== 'InjectedScript'); + + var summedChildrenDuration = 0; + if (record.children) { + record.children.forEach(function(child) { + summedChildrenDuration += processRecord(child, recordStats, isFunctionCall); + }); + } + var recordDuration; + var recordUsed = false; + // we need to substract the time of child records + // that have been added to the stats from this record. + // E.g. for a script record that triggered a gc or reflow while executing. + recordDuration = (record.endTime ? record.endTime - record.startTime : 0) + - summedChildrenDuration; + + if (isStarted) { + if (isFunctionCall) { + recordStats.script += recordDuration; + recordUsed = true; + } else if (record.type === 'GCEvent') { + recordStats.gcTime += recordDuration; + recordStats.gcAmount += record.data.usedHeapSizeDelta; + if (parentIsFunctionCall) { + recordStats.gcTimeDuringScript += recordDuration; + recordStats.gcAmountDuringScript += record.data.usedHeapSizeDelta; + } + recordUsed = true; + } else if (record.type === 'RecalculateStyles' || + record.type === 'Layout' || + record.type === 'UpdateLayerTree' || + record.type === 'Paint' || + record.type === 'Rasterize' || + record.type === 'CompositeLayers') { + recordStats.render += recordDuration; + recordUsed = true; + } else if (record.type === 'TimeStamp') { + recordStats.timeStamps.push(record.data.message); + } + } + + if (record.type === 'TimeStamp' && record.data.message === endTimeStampId) { + isStarted = false; + } + return recordUsed ? recordDuration : summedChildrenDuration; + } +} + diff --git a/tools/benchpress/tools.js b/tools/benchpress/tools.js new file mode 100644 index 0000000000..2eb0a3b553 --- /dev/null +++ b/tools/benchpress/tools.js @@ -0,0 +1,18 @@ +var webdriver = require('protractor/node_modules/selenium-webdriver'); + +module.exports = { + verifyNoBrowserErrors: verifyNoBrowserErrors +}; + +function verifyNoBrowserErrors() { + browser.manage().logs().get('browser').then(function(browserLog) { + var filteredLog = browserLog.filter(function(logEntry) { + return logEntry.level.value > webdriver.logging.Level.WARNING.value; + }); + expect(filteredLog.length).toEqual(0); + if (filteredLog.length) { + console.log('browser console errors: ' + require('util').inspect(filteredLog)); + } + }); +} + diff --git a/tools/perf/util.js b/tools/perf/util.js deleted file mode 100644 index cbfa3136eb..0000000000 --- a/tools/perf/util.js +++ /dev/null @@ -1,232 +0,0 @@ -var webdriver = require('protractor/node_modules/selenium-webdriver'); - -module.exports = { - perfLogs: perfLogs, - sumTimelineRecords: sumTimelineRecords, - runClickBenchmark: runClickBenchmark, - verifyNoErrors: verifyNoErrors, - printObjectAsMarkdown: printObjectAsMarkdown -}; - -function runClickBenchmark(config) { - var buttons = config.buttons.map(function(selector) { - return $(selector); - }); - var globalParams = browser.params; - - // empty perflogs queue and gc - gc(); - perfLogs(); - var sampleQueue = []; - var bestSampleStats = null; - - loop(globalParams.maxRepeatCount).then(function(stats) { - printObjectAsMarkdown(config.name, stats); - }); - - function loop(count) { - if (!count) { - return bestSampleStats; - } - return webdriver.promise.all(buttons.map(function(button) { - // Note: even though we remove the gc time from the script time, - // we still get a high standard devication if we don't gc after every click... - return button.click().then(gc); - })).then(function() { - return perfLogs(); - }).then(function(logs) { - var stats = calculateStatsBasedOnLogs(logs); - if (stats) { - if (stats.script.error < globalParams.exitOnErrorLowerThan) { - return stats; - } - if (!bestSampleStats || stats.script.error < bestSampleStats.script.error) { - bestSampleStats = stats; - } - } - return loop(count-1); - }); - } - - function calculateStatsBasedOnLogs(logs) { - sampleQueue.push(sumTimelineRecords(logs['Timeline.eventRecorded'])); - if (sampleQueue.length >= globalParams.sampleSize) { - sampleQueue.splice(0, sampleQueue.length - globalParams.sampleSize); - // TODO: gc numbers don't have much meaning right now, - // as a benchmark run destroys everything. - // We need to measure the heap size after gc as well! - return calculateObjectSampleStats(sampleQueue, ['script', 'render', 'gcTime', 'gcAmount']); - } - return null; - } -} - -function gc() { - // TODO(tbosch): this only works on chrome, and we actually should - // extend chromedriver to use the Debugger.CollectGarbage call of the - // remote debugger protocol. - // See http://src.chromium.org/viewvc/blink/trunk/Source/devtools/protocol.json - // For iOS Safari we need an extension to appium that uses - // the webkit remote debug protocol. See - // https://github.com/WebKit/webkit/blob/master/Source/WebInspectorUI/Versions/Inspector-iOS-8.0.json - return browser.executeScript('window.gc()'); -} - -function verifyNoErrors() { - browser.manage().logs().get('browser').then(function(browserLog) { - var filteredLog = browserLog.filter(function(logEntry) { - return logEntry.level.value > webdriver.logging.Level.WARNING.value; - }); - expect(filteredLog.length).toEqual(0); - if (filteredLog.length) { - console.log('browser console errors: ' + require('util').inspect(filteredLog)); - } - }); -} - -function perfLogs() { - return plainLogs('performance').then(function(entries) { - var entriesByMethod = {}; - entries.forEach(function(entry) { - var message = JSON.parse(entry.message).message; - var entries = entriesByMethod[message.method]; - if (!entries) { - entries = entriesByMethod[message.method] = []; - } - entries.push(message.params); - }); - return entriesByMethod; - }); -} - -// Needed as selenium-webdriver does not forward -// performance logs in the correct way -function plainLogs(type) { - var webdriver = require('protractor/node_modules/selenium-webdriver'); - return browser.driver.schedule( - new webdriver.Command(webdriver.CommandName.GET_LOG). - setParameter('type', type), - 'WebDriver.manage().logs().get(' + type + ')'); -}; - - -function sumTimelineRecords(messages) { - var recordStats = { - script: 0, - gcTime: 0, - gcAmount: 0, - render: 0 - }; - messages.forEach(function(message) { - processRecord(message.record, recordStats); - }); - return recordStats; - - function processRecord(record, recordStats) { - var summedChildrenDuration = 0; - if (record.children) { - record.children.forEach(function(child) { - summedChildrenDuration += processRecord(child, recordStats); - }); - } - - var recordDuration; - var recordUsed = false; - if (recordStats) { - // we need to substract the time of child records - // that have been added to the stats from this record. - // E.g. for a script record that triggered a gc or reflow while executing. - recordDuration = (record.endTime ? record.endTime - record.startTime : 0) - - summedChildrenDuration; - if (record.type === 'FunctionCall') { - if (!record.data || record.data.scriptName !== 'InjectedScript') { - // ignore scripts that were injected by Webdriver (e.g. calculation of element positions, ...) - recordStats.script += recordDuration; - recordUsed = true; - } - } else if (record.type === 'GCEvent') { - recordStats.gcTime += recordDuration; - recordStats.gcAmount += record.data.usedHeapSizeDelta; - recordUsed = true; - } else if (record.type === 'RecalculateStyles' || - record.type === 'Layout' || - record.type === 'UpdateLayerTree' || - record.type === 'Paint' || - record.type === 'Rasterize' || - record.type === 'CompositeLayers') { - recordStats.render += recordDuration; - recordUsed = true; - } - } - return recordUsed ? recordDuration : summedChildrenDuration; - } -} - -function printObjectAsMarkdown(name, obj) { - var props = [['name']]; - var vals = [name]; - flattenObj(obj, [], props, vals); - // log header - var separators = []; - var header = props.map(function(propPath) { - separators.push('----'); - return propPath.join('.'); - }).join(' | '); - console.log('\n'+header); - console.log(separators.join(' | ')); - console.log(vals.join(' | ')); - console.log('\n'); - - function flattenObj(obj, propPathPrefix, targetProps, targetVals) { - for (var prop in obj) { - var val = obj[prop]; - var currPropPath = propPathPrefix.concat([prop]); - if (val && typeof val === 'object') { - flattenObj(val, currPropPath, targetProps, targetVals); - } else { - targetProps.push(currPropPath); - var valStr = val; - if (typeof val === 'number') { - valStr = val.toFixed(2); - } - targetVals.push(valStr); - } - } - } -} - -function calculateObjectSampleStats(objectSamples, properties) { - var result = {}; - properties.forEach(function(prop) { - var samples = objectSamples.map(function(objectSample) { - return objectSample[prop]; - }); - var mean = calculateMean(samples); - var error = calculateCoefficientOfVariation(samples, mean); - result[prop] = { - mean: mean, - error: error - }; - }); - return result; -} - -function calculateCoefficientOfVariation(sample, mean) { - return calculateStandardDeviation(sample, mean) / mean * 100; -} - -function calculateMean(sample) { - var total = 0; - sample.forEach(function(x) { total += x; }); - return total / sample.length; -} - -function calculateStandardDeviation(sample, mean) { - var deviation = 0; - sample.forEach(function(x) { - deviation += Math.pow(x - mean, 2); - }); - deviation = deviation / (sample.length -1); - deviation = Math.sqrt(deviation); - return deviation; -}; \ No newline at end of file