feat(benchmark): record gc time for each test run

Author: jeffbcross

benchmark/web/bp.js

@@ -3,6 +3,7 @@ bp.steps = window.benchmarkSteps = [];
 bp.runState = {
   numSamples: 10,
   recentTimePerStep: {},
+  recentGCTimePerStep: {},
   timesPerAction: {}
 };
 
@@ -82,13 +83,25 @@ bp.runTimedTest = function (bs) {
   }
   var startTime = bp.numMilliseconds();
   bs.fn();
-  return bp.numMilliseconds() - startTime;
+  var endTime = bp.numMilliseconds() - startTime;
+
+  var startGCTime = bp.numMilliseconds();
+  if (typeof window.gc === 'function') {
+    window.gc();
+  }
+  var endGCTime = bp.numMilliseconds() - startGCTime;
+  return {
+    time: endTime,
+    gcTime: endGCTime
+  };
 };
 
 bp.runAllTests = function (done) {
   if (bp.runState.iterations--) {
     bp.steps.forEach(function(bs) {
-      bp.runState.recentTimePerStep[bs.name] = bp.runTimedTest(bs);
+      var testResults = bp.runTimedTest(bs);
+      bp.runState.recentTimePerStep[bs.name] = testResults.time;
+      bp.runState.recentGCTimePerStep[bs.name] = testResults.gcTime;
     });
     bp.report = bp.calcStats();
     bp.writeReport(bp.report);
@@ -103,20 +116,28 @@ bp.runAllTests = function (done) {
   }
 }
 
-bp.generateReportPartial = function(name, avg, times) {
+bp.generateReportPartial = function(name, avg, fmtTimes, gcTimes) {
   return bp.interpolateHtml(
-      '<tr><td>%0</td><td class="average">%1ms</td><td>[%2]ms</td></tr>',
+      '<tr><td>%0</td><td class="average">test:%1ms<br>gc:%2ms<br>combined: %3ms</td><td>%4</td><td>%5</td></tr>',
       [
         name,
-        ('' + avg).substr(0,6),
-        times.join(', ')
+        ('' + avg.time).substr(0,6),
+        ('' + avg.gcTime).substr(0,6),
+        ('' + (avg.time + avg.gcTime)).substr(0,6),
+        fmtTimes.join('<br>'),
+        gcTimes.join('<br>')
       ]);
 };
 
-bp.getAverage = function (times, runState) {
-  var avg = 0;
-  times.forEach(function(x) { avg += x; });
-  return avg / times.length;
+bp.getAverage = function (times, gcTimes, runState) {
+  var timesAvg = 0;
+  var gcAvg = 0;
+  times.forEach(function(x) { timesAvg += x; });
+  gcTimes.forEach(function(x) { gcAvg += x; });
+  return {
+    gcTime: gcAvg / gcTimes.length,
+    time: timesAvg / times.length
+  };
 };
 
 bp.writeReport = function(reportContent) {
@@ -129,6 +150,8 @@ bp.getTimesPerAction = function(name) {
     tpa = bp.runState.timesPerAction[name] = {
       times: [], // circular buffer
       fmtTimes: [],
+      fmtGCTimes: [],
+      gcTimes: [],
       nextEntry: 0
     }
   }
@@ -149,17 +172,25 @@ bp.calcStats = function() {
   bp.steps.forEach(function(bs) {
     var stepName = bs.name,
         timeForStep = bp.runState.recentTimePerStep[stepName],
+        gcTimeForStep = bp.runState.recentGCTimePerStep[stepName],
         tpa = bp.getTimesPerAction(stepName),
         avg;
 
-    tpa.fmtTimes[tpa.nextEntry] = ('' + timeForStep).substr(0,6);
+    tpa.fmtTimes[tpa.nextEntry] = timeForStep.toString().substr(0, 6);
     tpa.fmtTimes = bp.rightSizeTimes(tpa.fmtTimes);
+
+    tpa.fmtGCTimes[tpa.nextEntry] = gcTimeForStep.toString().substr(0, 6);
+    tpa.fmtGCTimes = bp.rightSizeTimes(tpa.fmtGCTimes);
+
+    tpa.gcTimes[tpa.nextEntry] = gcTimeForStep;
+    tpa.gcTimes = bp.rightSizeTimes(tpa.gcTimes);
+
     tpa.times[tpa.nextEntry++] = timeForStep;
     tpa.times = bp.rightSizeTimes(tpa.times);
-    tpa.nextEntry %= bp.runState.numSamples;
-    avg = bp.getAverage(tpa.times, bp.runState);
 
-    report += bp.generateReportPartial(stepName, avg, tpa.fmtTimes);
+    tpa.nextEntry %= bp.runState.numSamples;
+    avg = bp.getAverage(tpa.times, tpa.gcTimes);
+    report += bp.generateReportPartial(stepName, avg, tpa.fmtTimes, tpa.fmtGCTimes);
   });
   return report;
 };

benchmark/web/bp.spec.js

@@ -27,6 +27,7 @@ describe('bp', function() {
     bp.runState = {
       numSamples: 10,
       recentTimePerStep: {},
+      recentGCTimePerStep: {},
       timesPerAction: {}
     };
   });
@@ -283,7 +284,7 @@ describe('bp', function() {
 
     it('should return the time required to run the test', function() {
       var times = {};
-      expect(typeof bp.runTimedTest(mockStep, times)).toBe('number');
+      expect(typeof bp.runTimedTest(mockStep, times).time).toBe('number');
     });
   });
 
@@ -358,7 +359,10 @@ describe('bp', function() {
 
   describe('.getAverage()', function() {
     it('should return the average of a set of numbers', function() {
-      expect(bp.getAverage([100,0,50,75,25])).toBe(50);
+      expect(bp.getAverage([100,0,50,75,25], [2,4,2,4,3])).toEqual({
+        gcTime: 3,
+        time: 50
+      });
     });
   });
 
@@ -372,27 +376,37 @@ describe('bp', function() {
         recentTimePerStep: {
           fakeStep: 5
         },
+        recentGCTimePerStep: {
+          fakeStep: 2
+        },
         timesPerAction: {
           fakeStep: {
             times: [3,7],
             fmtTimes: ['3', '7'],
+            fmtGCTimes: ['1','3'],
+            gcTimes: [1,3],
             nextEntry: 2
           },
         }
       };
     });
 
+
     it('should call generateReportPartial() with the correct info', function() {
       var spy = spyOn(bp, 'generateReportPartial');
       bp.calcStats();
-      expect(spy).toHaveBeenCalledWith('fakeStep', 5, ['3','7','5']);
+      expect(spy).toHaveBeenCalledWith('fakeStep', {time: 5, gcTime: 2}, ['3','7','5'], ['1','3','2'])
+      expect(spy.calls[0].args[0]).toBe('fakeStep');
+      expect(spy.calls[0].args[1].gcTime).toBe(2);
+      expect(spy.calls[0].args[1].time).toBe(5);
+      expect(spy.calls[0].args[2]).toEqual(['3','7', '5']);
     });
 
 
     it('should call getAverage() with the correct info', function() {
-      var spy = spyOn(bp, 'getAverage');
+      var spy = spyOn(bp, 'getAverage').andCallThrough();
       bp.calcStats();
-      expect(spy).toHaveBeenCalledWith([3,7,5], bp.runState);
+      expect(spy).toHaveBeenCalledWith([ 3, 7, 5 ], [ 1, 3, 2 ]);
     });
 
 
@@ -414,8 +428,8 @@ describe('bp', function() {
   describe('.generateReportPartial()', function() {
     it('should return an html string with provided values', function() {
       bp.runState.numSamples = 9;
-      expect(bp.generateReportPartial('foo', 10, [9,11])).
-        toBe('<tr><td>foo</td><td class="average">10ms</td><td>[9, 11]ms</td></tr>')
+      expect(bp.generateReportPartial('foo', {time: 10, gcTime: 5}, ['9', '11'], ['4','6'])).
+        toBe('<tr><td>foo</td><td class="average">test:10ms<br>gc:5ms<br>combined: 15ms</td><td>9<br>11</td><td>4<br>6</td></tr>')
     });
   });
 

benchmark/web/tree.html

@@ -43,7 +43,8 @@
               <tr>
                 <th>step</th>
                 <th>average</th>
-                <th>samples</th>
+                <th>test time (ms)</th>
+                <th>gc time (ms)</th>
               </tr>
             </thead>
             <tbody class="info" style="font-family: monospace"></tbody>