Improvements to profiler report

Call counts, and visual improvements

tools/isobuild/compiler-plugin.js

@@ -141,7 +141,7 @@ export class CompilerPluginProcessor {
         " (for target ", self.arch, ")"
       ].join('');
 
-      Profile.time(jobTitle, () => {
+      Profile.time("plugin "+sourceProcessor.isopack.name, () => {
         buildmessage.enterJob({
           title: jobTitle
         }, function () {

tools/tool-env/profile.js

@@ -170,14 +170,54 @@ if (isNaN(filter)) {
   filter = 100; // ms
 }
 
-var bucketTimes = {};
+var bucketStats = {};
 
+var SPACES_STR = ' ';
+// return a string of `x` spaces
 var spaces = function (x) {
-  var s = '';
-  for (var i = 0; i < x; ++i) {
-    s += '  ';
+  while (SPACES_STR.length < x) {
+    SPACES_STR = SPACES_STR + SPACES_STR;
   }
-  return s;
+  return SPACES_STR.slice(0, x);
+};
+
+var DOTS_STR = '.';
+// return a string of `x` dots
+var dots = function (x) {
+  while (DOTS_STR.length < x) {
+    DOTS_STR = DOTS_STR + DOTS_STR;
+  }
+  return DOTS_STR.slice(0, x);
+};
+
+
+var leftAlign = function (str, len) {
+  if (str.length < len) {
+    str = str + spaces(len - str.length);
+  }
+  return str;
+};
+
+var rightAlign = function (str, len) {
+  if (str.length < len) {
+    str = spaces(len - str.length) + str;
+  }
+  return str;
+};
+
+var leftRightAlign = function (str1, str2, len) {
+  var middle = Math.max(1, len - str1.length - str2.length);
+  return str1 + spaces(middle) + str2;
+};
+
+var leftRightDots = function (str1, str2, len) {
+  var middle = Math.max(1, len - str1.length - str2.length);
+  return str1 + dots(middle) + str2;
+};
+
+var formatMs = function (n) {
+  // integer with thousands separators
+  return String(Math.round(n)).replace(/\B(?=(\d{3})+(?!\d))/g, ",") + " ms";
 };
 
 var globalEntry = [];
@@ -185,7 +225,7 @@ var globalEntry = [];
 var running = false;
 
 var start = function () {
-  bucketTimes = {};
+  bucketStats = {};
   running = true;
 };
 
@@ -226,8 +266,11 @@ var Profile = function (bucketName, f) {
     }
     finally {
       var elapsed = process.hrtime(start);
-      bucketTimes[key] = (bucketTimes[key] || 0) +
-        (elapsed[0] * 1000 + elapsed[1] / 1000000);
+      var stats = (bucketStats[key] || (bucketStats[key] = {
+        time: 0.0, count: 0
+      }));
+      stats.time += (elapsed[0] * 1000 + elapsed[1] / 1000000);
+      stats.count++;
       currentEntry.pop();
     }
 
@@ -249,8 +292,12 @@ var entryName = function (entry) {
   return _.last(entry);
 };
 
+var entryStats = function (entry) {
+  return bucketStats[JSON.stringify(entry)];
+};
+
 var entryTime = function (entry) {
-  return bucketTimes[JSON.stringify(entry)];
+  return entryStats(entry).time;
 };
 
 var isTopLevelEntry = function (entry) {
@@ -261,8 +308,8 @@ var topLevelEntries = function () {
   return _.filter(entries, isTopLevelEntry);
 };
 
-var print = function (indent, text) {
-  console.log(prefix + spaces(indent * 2) + text);
+var print = function (text) {
+  console.log(prefix + text);
 };
 
 var isChild = function (entry1, entry2) {
@@ -292,19 +339,10 @@ var isLeaf = function (entry) {
   return ! hasChildren(entry);
 };
 
-var reportOnLeaf = function (level, entry) {
-  if (entryTime(entry) < filter) {
-    return;
-  }
-  print(
-    level,
-    _.last(entry) + ": " + entryTime(entry).toFixed(1));
-};
-
 var otherTime = function (entry) {
   var total = 0;
   _.each(children(entry), function (child) {
-    total += bucketTimes[JSON.stringify(child)];
+    total += entryTime(child);
   });
   return entryTime(entry) - total;
 };
@@ -313,25 +351,29 @@ var injectOtherTime = function (entry) {
   var name = "other " + entryName(entry);
   var other = _.clone(entry);
   other.push(name);
-  bucketTimes[JSON.stringify(other)] = otherTime(entry);
+  bucketStats[JSON.stringify(other)] = {
+    time: otherTime(entry),
+    count: 0,
+    isOther: true
+  };
   entries.push(other);
 };
 
-var reportOnParent = function (level, entry) {
-  if (entryTime(entry) < filter) {
+var reportOn = function (level, entry) {
+  var stats = entryStats(entry);
+  if (stats.time < filter) {
     return;
   }
-  print(level, entryName(entry) + ": " + entryTime(entry).toFixed(1));
-  _.each(children(entry), function (child) {
-    reportOn(level + 1, child);
-  });
-};
+  var isParent = hasChildren(entry);
+  var name = entryName(entry);
+  print((isParent ? leftRightDots : leftRightAlign)
+        (spaces(level * 3) + name, formatMs(stats.time), 70)
+        + (stats.count ? (" (" + stats.count + ")") : ""));
 
-var reportOn = function (level, entry) {
-  if (hasChildren(entry)) {
-    reportOnParent(level, entry);
-  } else {
-    reportOnLeaf(level, entry);
+  if (isParent) {
+    _.each(children(entry), function (child) {
+      reportOn(level + 1, child);
+    });
   }
 };
 
@@ -358,7 +400,8 @@ var leafTotal = function (leafName) {
   return total;
 };
 
-var reportTotals = function () {
+var reportHotLeaves = function () {
+  print('Top leaves:');
   var totals = [];
   _.each(allLeafs(), function (leaf) {
     totals.push({name: leaf, time: leafTotal(leaf)});
@@ -366,19 +409,24 @@ var reportTotals = function () {
   totals.sort(function (a, b) {
     return a.time === b.time ? 0 : a.time > b.time ? -1 : 1;
   });
-  var grandTotal = 0;
   _.each(totals, function (total) {
     if (total.time < filter) {
       return;
     }
-    print(0, total.name + ": " + total.time.toFixed(1));
-    grandTotal += total.time;
+    print(leftRightDots(total.name, formatMs(total.time), 65));
   });
-  print(0, "Total: " + grandTotal.toFixed(1));
+};
+
+var getTopLevelTotal = function () {
+  var topTotal = 0;
+  _.each(topLevelEntries(), function (entry) {
+    topTotal += entryTime(entry);
+  });
+  return topTotal;
 };
 
 var setupReport = function () {
-  entries = _.map(_.keys(bucketTimes), JSON.parse);
+  entries = _.map(_.keys(bucketStats), JSON.parse);
   _.each(_.filter(entries, hasChildren), function (parent) {
     injectOtherTime(parent);
   });
@@ -389,11 +437,13 @@ var report = function () {
     return;
   }
   running = false;
-  print(0, '');
+  print('');
   setupReport();
   reportHierarchy();
-  print(0, '');
-  reportTotals();
+  print('');
+  reportHotLeaves();
+  print('');
+  print('Total: ' + formatMs(getTopLevelTotal()));
 };
 
 var run = function (bucketName, f) {