tools/tool-env/profile-require.js
// Use path instead of files.js here because we are explicitly trying to
// track requires, and files.js is often a culprit of slow requires.
var path = require('path');
// seconds since epoch
var now = function () {
return (+ new Date)/1000;
};
var currentInvocation;
var RequireInvocation = function (name, filename) {
var self = this;
self.name = name; // module required
self.filename = filename; // file doing the requiring, if known
self.timeStarted = now();
self.timeFinished = null;
self.parent = currentInvocation;
self.children = []; // array of RequireInvocation
self.selfTime = null;
self.totalTime = null;
};
RequireInvocation.prototype.isOurCode = function () {
var self = this;
if (! self.filename) {
return self.name === 'TOP';
}
if (! self.name.match(/\//)) {
// we always require our stuff via a path
return false;
}
var ourSource = path.resolve(__dirname);
var required = path.resolve(path.dirname(self.filename), self.name);
if (ourSource.length > required.length) {
return false;
}
return required.substr(0, ourSource.length) === ourSource;
};
RequireInvocation.prototype.why = function () {
var self = this;
var walk = self;
var last = null;
while (walk && ! walk.isOurCode()) {
last = walk;
walk = walk.parent;
}
if (! walk) {
return "???";
}
if (last) {
return path.basename(walk.name) + ":" + path.basename(last.name);
}
return path.basename(walk.name);
};
exports.start = function () {
var moduleModule = require('module');
currentInvocation = new RequireInvocation('TOP');
var realLoader = moduleModule._load;
moduleModule._load = function (...args) {
var [id, { filename }] = args;
var inv = new RequireInvocation(id, filename);
var parent = currentInvocation;
currentInvocation.children.push(inv);
currentInvocation = inv;
try {
return realLoader.apply(this, args);
} finally {
inv.timeFinished = now();
currentInvocation = parent;
}
};
};
exports.printReport = function () {
currentInvocation.timeFinished = now();
var _ = require('underscore');
var computeTimes = function (inv) {
inv.totalTime = inv.timeFinished - inv.timeStarted;
var childTime = 0;
_.each(inv.children, function (child) {
computeTimes(child);
childTime += child.totalTime;
});
if (inv.totalTime !== null) {
inv.selfTime = inv.totalTime - childTime;
}
};
computeTimes(currentInvocation);
var summary = {};
var summarize = function (inv, depth) {
// var padding = (new Array(depth*2 + 1)).join(' ');
// console.log(padding + inv.name + " [" + inv.selfTime + "]");
if (! (inv.name in summary)) {
summary[inv.name] = { name: inv.name, time: 0, ours: inv.isOurCode(),
via: {} };
}
summary[inv.name].time += inv.selfTime;
if (! inv.isOurCode()) {
summary[inv.name].via[inv.why()] = true;
}
_.each(inv.children, function (inv) {
summarize(inv, depth + 1);
});
};
summarize(currentInvocation, 0);
var times = _.sortBy(_.values(summary), 'time').reverse();
var ourTotal = 0, otherTotal = 0;
_.each(times, function (item) {
var line = (item.time * 1000).toFixed(2) + " " + item.name;
if (! item.ours) {
line += " [via " + Object.keys(item.via).join(", ") + "]";
}
console.log(line);
if (item.ours) {
ourTotal += item.time;
} else {
otherTotal += item.time;
}
});
var grandTotal = currentInvocation.totalTime;
if (grandTotal - ourTotal - otherTotal > 1/1000) {
throw new Error("Times don't add up");
}
console.log("TOTAL: ours " + (ourTotal * 1000).toFixed(2) +
", other " + (otherTotal * 1000).toFixed(2) +
", grand total " + (grandTotal * 1000).toFixed(2));
};