Benchmarking and Performance Work

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']);
+});

benchmarks/simple-build.js

@@ -0,0 +1,17 @@
+var profile = require('../lib/profile');
+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');
+
+builder.bundle('first.js')
+.then(function() {
+  buildEvt.done();
+  profile.logSummary(['canonicalization']);
+});

index.js

@@ -1 +1,6 @@
+var profile = require('./lib/profile');
+var evt = profile.event('startup');
+
 module.exports = require('./lib/builder');
+
+evt.done();

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');
 });
@@ -168,7 +170,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) {

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,17 @@ 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', function() {
+    return 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 +199,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,

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);
 

lib/profile.js

@@ -0,0 +1,155 @@
+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 = (typeof item == 'function' ? 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() {}, cancel: function() {}, cancelIfNotDone: function() {} };
+
+Profile.event = function(eventName, eventItem) {
+  if (!enabled)
+    return nullEvent;
+
+  var evt = new ProfileEvent(eventName, eventItem);
+  events.push(evt);
+  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 = {};
+  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 + ')' : ''));
+}

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;
   });
 };