From ade7a9f2cd51353749ab37c2453b1e8884b9d57d Mon Sep 17 00:00:00 2001 From: guybedford Date: Wed, 23 Sep 2015 15:48:44 +0200 Subject: [PATCH 1/5] simple benchmarking --- benchmarks/simple-build.js | 13 ++++ index.js | 6 ++ lib/builder.js | 7 +- lib/compile.js | 10 ++- lib/output.js | 4 + lib/profile.js | 147 +++++++++++++++++++++++++++++++++++++ lib/trace.js | 10 +++ lib/utils.js | 40 ++++++---- 8 files changed, 219 insertions(+), 18 deletions(-) create mode 100644 benchmarks/simple-build.js create mode 100644 lib/profile.js diff --git a/benchmarks/simple-build.js b/benchmarks/simple-build.js new file mode 100644 index 0000000..db89121 --- /dev/null +++ b/benchmarks/simple-build.js @@ -0,0 +1,13 @@ +var profile = require('../lib/profile'); +profile.enable(); + +var buildEvt = profile.event('simple-build'); + +var Builder = require('../index'); +var builder = new Builder('test/fixtures/test-tree', 'test/fixtures/test-tree.config.js'); + +builder.bundle('first.js') +.then(function() { + buildEvt.done(); + profile.logSummary(['canonicalization']); +}); \ No newline at end of file diff --git a/index.js b/index.js index e3b203e..99718bc 100644 --- a/index.js +++ b/index.js @@ -1 +1,7 @@ +var profile = require('./lib/profile'); + +var evt = profile.event('startup'); + module.exports = require('./lib/builder'); + +evt.done(); \ No newline at end of file diff --git a/lib/builder.js b/lib/builder.js index 6266651..1f40fc0 100644 --- a/lib/builder.js +++ b/lib/builder.js @@ -19,6 +19,8 @@ var Trace = require('./trace'); var getCanonicalName = require('./utils').getCanonicalName; +var profile = require('./profile'); + require('rsvp').on('error', function(reason) { throw new Error('Unhandled promise rejection.\n' + reason && reason.stack || reason || '' + '\n'); }); @@ -45,6 +47,7 @@ function Builder(baseURL, cfg) { } Builder.prototype.reset = function(baseLoader) { + var evt = profile.event('reset-loader'); baseLoader = baseLoader || this.loader || System; var loader = this.loader = new baseLoader.constructor(); @@ -136,6 +139,8 @@ Builder.prototype.reset = function(baseLoader) { // clear the cache this.setCache({}); + + evt.done(); }; Builder.prototype.setCache = function(cacheObj) { @@ -168,7 +173,7 @@ function executeConfigFile(saveForReset, ignoreBaseURL, source) { Builder.prototype.loadConfig = function(configFile, saveForReset, ignoreBaseURL) { return asp(fs.readFile)(configFile) - .then(executeConfigFile.bind(this, saveForReset, ignoreBaseURL)); + .then(executeConfigFile.bind(this, saveForReset, ignoreBaseURL)) }; Builder.prototype.loadConfigSync = function(configFile, saveForReset, ignoreBaseURL) { diff --git a/lib/compile.js b/lib/compile.js index 83c7d05..5673bf8 100644 --- a/lib/compile.js +++ b/lib/compile.js @@ -10,6 +10,7 @@ var getTreeModulesPostOrder = require('./trace').getTreeModulesPostOrder; var extend = require('./utils').extend; var dextend = require('./utils').dextend; var getPackage = require('./utils').getPackage; +var profile = require('./profile'); var compilerMap = { 'amd': '../compilers/amd', @@ -94,9 +95,12 @@ function compileLoad(loader, load, compileOpts, cache) { if (format == 'defined') return Promise.resolve({ source: compileOpts.systemGlobal + '.register("' + mappedLoad.name + '", [], function() { return { setters: [], execute: function() {} } });\n' }); - if (format in compilerMap) + if (format in compilerMap) { + var evt = profile.event('compile', load.name); return Promise.resolve(require(compilerMap[format]).compile(mappedLoad, compileOpts, loader)) .then(function(output) { + evt.done(); + // store compiled output in cache cache.loads[load.name] = { hash: getCompileHash(load, compileOpts), @@ -105,12 +109,15 @@ function compileLoad(loader, load, compileOpts, cache) { return output; }); + } return Promise.reject(new TypeError('Unknown module format ' + format)); } exports.compileTree = compileTree; function compileTree(loader, tree, compileOpts, outputOpts, cache) { + var evt = profile.event('compile-tree', Object.keys(tree).join(', ')); + // sort in graph order, filter modules to actually built loads (excluding conditionals, build: false) var ordered = getTreeModulesPostOrder(tree); // get entrypoints from graph algorithm @@ -190,6 +197,7 @@ function compileTree(loader, tree, compileOpts, outputOpts, cache) { return addPackageConfig(loader, tree, outputs, entryPoints, compileOpts); }) .then(function(outputs) { + evt.done(); // NB also include all aliases of all entryPoints along with entryPoints return { outputs: outputs, diff --git a/lib/output.js b/lib/output.js index 6168764..f16a49b 100644 --- a/lib/output.js +++ b/lib/output.js @@ -3,6 +3,7 @@ var mkdirp = require('mkdirp'); var fs = require('fs'); var Promise = require('rsvp').Promise; var asp = require('rsvp').denodeify; +var profile = require('./profile'); var fromFileURL = require('./utils').fromFileURL; var toFileURL = require('./utils').toFileURL; @@ -140,6 +141,7 @@ function inlineSourceMap(source, sourceMap) { } exports.writeOutputs = function(outputs, baseURL, outputOpts) { + var evt = profile.event('concatenate'); var outFile = outputOpts.outFile && path.resolve(outputOpts.outFile); var basePath = fromFileURL(baseURL); var fileName = path.basename(outFile) || 'output.js'; @@ -154,6 +156,8 @@ exports.writeOutputs = function(outputs, baseURL, outputOpts) { output.sourceMap = undefined; } + evt.done(); + if (!outputOpts.outFile) return Promise.resolve(output); diff --git a/lib/profile.js b/lib/profile.js new file mode 100644 index 0000000..1fdb2ee --- /dev/null +++ b/lib/profile.js @@ -0,0 +1,147 @@ +var Profile = module.exports; + +// profiling events +var events = []; + +// profiling is enabled via profile.enable() or `--profile` flag +var enabled = process.argv.indexOf('--profile') != -1; +Profile.enable = function() { + enabled = true; +}; + +function ProfileEvent(name, item) { + this.name = name; + this.item = item || 'default'; + this.start = Date.now(); + this.stop = null; + this.cancelled = false; +} +ProfileEvent.prototype.rename = function(name, item) { + this.name = name; + if (arguments.length > 1) + this.item = item; +}; +ProfileEvent.prototype.done = function() { + if (this.stop) + throw new TypeError('Event ' + name + ' (' + this.item + ') has already completed.'); + this.stop = Date.now(); +}; +ProfileEvent.prototype.cancel = function() { + this.cancelled = true; +}; +ProfileEvent.prototype.cancelIfNotDone = function() { + if (!this.stop) + this.cancelled = true; +}; + +var nullEvent = { done: function() {} }; + +Profile.event = function(eventName, eventItem) { + if (!enabled) + return nullEvent; + + var evt = new ProfileEvent(eventName, eventItem); + events.push(evt); + return evt; +}; + +Profile.logSummary = function(excludeEvts) { + // create groupings of events by event name to time data + // filtering out cancelled events + var groupedEvents = {}; + events.forEach(function(evt) { + if (excludeEvts.indexOf(evt.name) != -1) + return; + if (evt.cancelled) + return; + if (!evt.stop) + throw new TypeError('Event ' + evt.name + ' (' + evt.item + ') never completed.'); + + var evtTimes = groupedEvents[evt.name] = groupedEvents[evt.name] || []; + evtTimes.push({ + time: evt.stop - evt.start, + item: evt.item + }); + }); + + Object.keys(groupedEvents).forEach(function(evt) { + var evtTimes = groupedEvents[evt]; + + // only one event -> log as a single event + if (evtTimes.length == 1) { + console.log(toTitleCase(evt) + (evtTimes[0].item != 'default' ? ' (' + evtTimes[0].item + ')' : '')); + logStat('Total Time', evtTimes[0].time); + console.log(''); + return; + } + + // multiple events, give some stats! + var evtCount = evtTimes.length; + + console.log(toTitleCase(evt) + ' (' + evtCount + ' events)'); + + var totalTime = evtTimes.reduce(function(curSum, evt) { + return curSum + evt.time; + }, 0); + logStat('Cumulative Time', totalTime); + + var mean = totalTime / evtCount; + logStat('Mean', mean); + + var stdDev = Math.sqrt(evtTimes.reduce(function(curSum, evt) { + return curSum + Math.pow(evt.time - mean, 2); + }, 0) / evtCount); + + logStat('Std Deviation', stdDev); + + var withoutOutliers = evtTimes.filter(function(evt) { + return evt.time > mean - stdDev && evt.time < mean + stdDev; + }); + + logStat('Avg within 2σ', withoutOutliers.reduce(function(curSum, evt) { + return curSum + evt.time; + }, 0) / withoutOutliers.length); + + var sorted = evtTimes.sort(function(a, b) { + return a.time > b.time ? 1 : -1; + }); + + var medianIndex = Math.round(evtCount / 2); + logStat('Median', sorted[medianIndex].time, sorted[medianIndex].evt); + + logStat('Max', sorted[evtCount - 1].time, sorted[evtCount - 1].item); + + logStat('Min', sorted[0].time, sorted[0].item); + + var duplicates = evtTimes.filter(function(evt) { + return evtTimes.some(function(dup) { + return dup !== evt && dup.name == evt.name && dup.item == evt.item; + }); + }); + + logStat('Duplicate Events', duplicates.length, true); + + logStat('Total Duplicated Time', duplicates.reduce(function(duplicateTime, evt) { + return duplicateTime + evt.time; + }, 0)); + + console.log(''); + }); +}; + +function toTitleCase(title) { + return title.split('-').map(function(part) { + return part[0].toUpperCase() + part.substr(1); + }).join(' '); +} + +var titleLen = 25; +function logStat(title, value, item, isNum) { + if (item === true) { + item = undefined; + isNum = true; + } + var spaces = Array(titleLen - title.length + 1).join(' '); + var value = isNum ? value : Math.round(value * 100) / 100 + 'ms'; + console.log(' ' + title + spaces + ': ' + value + (item ? ' (' + item + ')' : '')); +} \ No newline at end of file diff --git a/lib/trace.js b/lib/trace.js index 94ca40c..2c48b10 100644 --- a/lib/trace.js +++ b/lib/trace.js @@ -8,6 +8,7 @@ var Graph = require('algorithms/data_structures/graph'); var depthFirst = require('algorithms/graph').depthFirstSearch; var path = require('path'); var extend = require('./utils').extend; +var profile = require('./profile'); module.exports = Trace; @@ -27,6 +28,8 @@ Trace.prototype.traceModule = function(moduleName, traceAllConditionals, conditi var loader = this.loader; var self = this; + + var evt = profile.event('deep-trace', moduleName); return Promise.resolve(loader.normalize(moduleName)) .then(function(_moduleName) { @@ -48,6 +51,8 @@ Trace.prototype.traceModule = function(moduleName, traceAllConditionals, conditi loads[curMatch[3].substr(1, curMatch[3].length - 2)] = true; } + evt.done(); + return { moduleName: moduleName, tree: loads @@ -73,6 +78,8 @@ Trace.prototype.getLoadRecord = function(canonical) { if (this.tracing[canonical]) return this.tracing[canonical]; + var evt = profile.event('trace', canonical); + var self = this; var isPackageConditional = canonical.indexOf('#:') != -1; return this.tracing[canonical] = Promise.resolve(loader.normalize(canonical)) @@ -329,11 +336,14 @@ Trace.prototype.getLoadRecord = function(canonical) { delete load.metadata.builderExecute; delete load.metadata.parseTree; + evt.done(); + return load; }); }); }) .then(function(load) { + evt.cancelIfNotDone(); return loads[canonical] = load; }); }; diff --git a/lib/utils.js b/lib/utils.js index 5bb474d..7fe854b 100644 --- a/lib/utils.js +++ b/lib/utils.js @@ -1,5 +1,6 @@ var path = require('path'); var url = require('url'); +var profile = require('./profile'); exports.extend = extend; function extend(a, b) { @@ -64,34 +65,41 @@ function getAlias(loader, canonicalName) { exports.getCanonicalName = getCanonicalName; function getCanonicalName(loader, normalized, isPlugin) { + var evt = profile.event('canonicalization', normalized + (isPlugin ? ' (plugin)' : '')); + + var canonical; + + var index, conditionalMatch; + // 1. Boolean conditional - var booleanIndex = normalized.lastIndexOf('#?'); - if (booleanIndex != -1) { - var booleanModule = normalized.substr(booleanIndex + 2); + if ((index = normalized.lastIndexOf('#?')) != -1) { + var booleanModule = normalized.substr(index + 2); var negate = booleanModule[0] == '~'; if (negate) booleanModule = booleanModule.substr(1); - return getCanonicalName(loader, normalized.substr(0, booleanIndex)) + '#?' + (negate ? '~' : '') + canonicalizeCondition(loader, booleanModule); + canonical = getCanonicalName(loader, normalized.substr(0, index)) + '#?' + (negate ? '~' : '') + canonicalizeCondition(loader, booleanModule); } // 2. Plugins - var pluginIndex = loader.pluginFirst ? normalized.indexOf('!') : normalized.lastIndexOf('!'); - if (pluginIndex != -1) - return getCanonicalName(loader, normalized.substr(0, pluginIndex), !loader.pluginFirst) + '!' + getCanonicalName(loader, normalized.substr(pluginIndex + 1), loader.pluginFirst); + else if ((index = loader.pluginFirst ? normalized.indexOf('!') : normalized.lastIndexOf('!')) != -1) { + canonical = getCanonicalName(loader, normalized.substr(0, index), !loader.pluginFirst) + '!' + getCanonicalName(loader, normalized.substr(index + 1), loader.pluginFirst); + } // 3. Package environment map - var pkgEnvIndex = normalized.indexOf('#:'); - if (pkgEnvIndex != -1) - return getCanonicalName(loader, normalized.substr(0, pkgEnvIndex), isPlugin) + normalized.substr(pkgEnvIndex); + else if ((index = normalized.indexOf('#:')) != -1) { + canonical = getCanonicalName(loader, normalized.substr(0, index), isPlugin) + normalized.substr(index); + } // Finally get canonical plain - var canonical = getCanonicalNamePlain(loader, normalized, isPlugin); - - // 4. Canonicalize conditional interpolation - var conditionalMatch = canonical.match(interpolationRegEx); - if (conditionalMatch) - return getCanonicalNamePlain(loader, normalized, isPlugin).replace(interpolationRegEx, '#{' + canonicalizeCondition(loader, conditionalMatch[0].substr(2, conditionalMatch[0].length - 3)) + '}'); + else { + canonical = getCanonicalNamePlain(loader, normalized, isPlugin); + + // 4. Canonicalize conditional interpolation + if (conditionalMatch = canonical.match(interpolationRegEx)) + canonical = getCanonicalNamePlain(loader, normalized, isPlugin).replace(interpolationRegEx, '#{' + canonicalizeCondition(loader, conditionalMatch[0].substr(2, conditionalMatch[0].length - 3)) + '}'); + } + evt.done(); return canonical; } From 29c5bfb73cb1af37848738a25025a038397c86ba Mon Sep 17 00:00:00 2001 From: guybedford Date: Wed, 23 Sep 2015 15:52:30 +0200 Subject: [PATCH 2/5] test fix --- lib/profile.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/profile.js b/lib/profile.js index 1fdb2ee..06de7da 100644 --- a/lib/profile.js +++ b/lib/profile.js @@ -34,7 +34,7 @@ ProfileEvent.prototype.cancelIfNotDone = function() { this.cancelled = true; }; -var nullEvent = { done: function() {} }; +var nullEvent = { done: function() {}, cancel: function() {}, cancelIfNotDone: function() {} }; Profile.event = function(eventName, eventItem) { if (!enabled) From d8af857777e7e9e2b57080b744461af3d67c6b62 Mon Sep 17 00:00:00 2001 From: guybedford Date: Wed, 23 Sep 2015 16:00:27 +0200 Subject: [PATCH 3/5] avoid tree concats in production --- lib/compile.js | 4 +++- lib/profile.js | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/lib/compile.js b/lib/compile.js index 5673bf8..03522c0 100644 --- a/lib/compile.js +++ b/lib/compile.js @@ -116,7 +116,9 @@ function compileLoad(loader, load, compileOpts, cache) { exports.compileTree = compileTree; function compileTree(loader, tree, compileOpts, outputOpts, cache) { - var evt = profile.event('compile-tree', Object.keys(tree).join(', ')); + var evt = profile.event('compile-tree', function() { + return Object.keys(tree).join(', '); + }); // sort in graph order, filter modules to actually built loads (excluding conditionals, build: false) var ordered = getTreeModulesPostOrder(tree); diff --git a/lib/profile.js b/lib/profile.js index 06de7da..42fe634 100644 --- a/lib/profile.js +++ b/lib/profile.js @@ -11,7 +11,7 @@ Profile.enable = function() { function ProfileEvent(name, item) { this.name = name; - this.item = item || 'default'; + this.item = (typeof item == 'function' ? item() : item) || 'default'; this.start = Date.now(); this.stop = null; this.cancelled = false; From f08fd6b27f1ce8d742fc1e059433d579b6550527 Mon Sep 17 00:00:00 2001 From: guybedford Date: Wed, 23 Sep 2015 17:31:52 +0200 Subject: [PATCH 4/5] cache build test --- benchmarks/cached-tree-build.js | 23 +++++++++++++++++++++++ benchmarks/simple-build.js | 4 ++++ index.js | 1 - lib/builder.js | 3 --- 4 files changed, 27 insertions(+), 4 deletions(-) create mode 100644 benchmarks/cached-tree-build.js diff --git a/benchmarks/cached-tree-build.js b/benchmarks/cached-tree-build.js new file mode 100644 index 0000000..1d57539 --- /dev/null +++ b/benchmarks/cached-tree-build.js @@ -0,0 +1,23 @@ +var profile = require('../lib/profile'); + +var Builder = require('../index'); +var builder = new Builder('test/fixtures/test-tree', 'test/fixtures/test-tree.config.js'); + +var buildEvt; + +// First warm up the cache +builder.bundle('first.js') +.then(function() { + var cache = builder.getCache(); + + // now do the bundle operation again against the cache + profile.enable(); + buildEvt = profile.event('cached-tree-build'); + builder.reset(); + builder.setCache(cache); + return builder.bundle('first.js') +}) +.then(function() { + buildEvt.done(); + profile.logSummary(['canonicalization', 'startup']); +}); \ No newline at end of file diff --git a/benchmarks/simple-build.js b/benchmarks/simple-build.js index db89121..30976ee 100644 --- a/benchmarks/simple-build.js +++ b/benchmarks/simple-build.js @@ -3,6 +3,10 @@ profile.enable(); var buildEvt = profile.event('simple-build'); +var traceurEvt = profile.event('loading-traceur'); +require('traceur'); +traceurEvt.done(); + var Builder = require('../index'); var builder = new Builder('test/fixtures/test-tree', 'test/fixtures/test-tree.config.js'); diff --git a/index.js b/index.js index 99718bc..c3f15db 100644 --- a/index.js +++ b/index.js @@ -1,5 +1,4 @@ var profile = require('./lib/profile'); - var evt = profile.event('startup'); module.exports = require('./lib/builder'); diff --git a/lib/builder.js b/lib/builder.js index 1f40fc0..768b921 100644 --- a/lib/builder.js +++ b/lib/builder.js @@ -47,7 +47,6 @@ function Builder(baseURL, cfg) { } Builder.prototype.reset = function(baseLoader) { - var evt = profile.event('reset-loader'); baseLoader = baseLoader || this.loader || System; var loader = this.loader = new baseLoader.constructor(); @@ -139,8 +138,6 @@ Builder.prototype.reset = function(baseLoader) { // clear the cache this.setCache({}); - - evt.done(); }; Builder.prototype.setCache = function(cacheObj) { From cd4638ed50e440b823f87aa9ce2fb90c7c76931c Mon Sep 17 00:00:00 2001 From: guybedford Date: Thu, 24 Sep 2015 14:33:47 +0200 Subject: [PATCH 5/5] auto log on exit --- lib/profile.js | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/lib/profile.js b/lib/profile.js index 42fe634..5b52fad 100644 --- a/lib/profile.js +++ b/lib/profile.js @@ -45,7 +45,15 @@ Profile.event = function(eventName, eventItem) { return evt; }; +process.on('exit', function() { + if (!logged) + Profile.logSummary(); +}); + +var logged = false; Profile.logSummary = function(excludeEvts) { + excludeEvts = excludeEvts || []; + logged = true; // create groupings of events by event name to time data // filtering out cancelled events var groupedEvents = {};