Merge pull request #38 from pereckerdal/measure-test-time

Measure the time for each test and report it

lib/reporter/spec_progress.js

@@ -55,6 +55,11 @@ var nameColors = {
   defaultColor: chalk.grey
 };
 
+var slownessColors = {
+  slow: chalk.red,
+  halfSlow: chalk.yellow
+};
+
 function color(palette, name) {
   return palette[name] || palette.defaultColor || function(x) { return x; };
 }
@@ -129,6 +134,10 @@ SpecProgress.prototype.gotMessage = function(testPath, message) {
     this._log.logAfter(this._lastLineIdForSuite[suitePathAsString], line, pathAsString);
     this._lastLineIdForSuite[suitePathAsString] = pathAsString;
   } else if (message.type === 'finish') {
+    if (message.time && (message.slow || message.halfSlow)) {
+      var slownessColor = slownessColors[message.slow ? 'slow' : 'halfSlow'];
+      line += slownessColor(' (' + Math.round(message.time) + 'ms)');
+    }
     this._log.replace(pathAsString, line);
   }
 };

lib/reporter/timer.js

@@ -0,0 +1,83 @@
+/*
+ * Copyright 2014 Per Eckerdal
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+'use strict';
+
+/**
+ * Timer is a reporter for internal use by the suite runner. It forwards all
+ * messages to another reporter, but also adds "time", "slow" and "halfSlow"
+ * fields to finish messages.
+ *
+ * This is used in the suite runner as a way to move logic out of that file.
+ */
+function Timer(reporter, defaultSlowThreshold, clock) {
+  if (typeof defaultSlowThreshold !== 'number') {
+    throw new Error('Invalid or missing default slow threshold parameter');
+  }
+
+  this._reporter = reporter;
+  this._defaultSlowThreshold = defaultSlowThreshold;
+  this._slowThresholdOverrides = {};  // Hash from test path JSON to overriden slow threshold
+  this._testStartTimes = {};  // Hash from test path JSON to test start times (as given by the clock)
+  this._testDoneTimes = {};  // Hash from test path JSON to test done times (as given by the clock)
+  this._clock = clock || function() { return (new Date()).getTime(); };
+}
+
+Timer.prototype._getSlowThresholdForTest = function(key) {
+  return key in this._slowThresholdOverrides ?
+    this._slowThresholdOverrides[key] :
+    this._defaultSlowThreshold;
+};
+
+Timer.prototype._setSlowThresholdForTest = function(key, value) {
+  this._slowThresholdOverrides[key] = value;
+};
+
+Timer.prototype._forwardCall = function(message, args) {
+  if (this._reporter[message]) {
+    this._reporter[message].apply(this._reporter, args);
+  }
+};
+
+['registrationFailed', 'registerTests', 'done'].forEach(function(message) {
+  Timer.prototype[message] = function() {
+    this._forwardCall(message, arguments);
+  };
+});
+
+Timer.prototype.gotMessage = function(testPath, message) {
+  var key = JSON.stringify(testPath);
+  if (message.type === 'startedTest') {
+    this._testStartTimes[key] = this._clock();
+  } else if (message.type === 'startedAfterHooks') {
+    this._testDoneTimes[key] = this._clock();
+  } else if (message.type === 'setSlowThreshold') {
+    this._setSlowThresholdForTest(key, message.value);
+  } else if (message.type === 'finish') {
+    if (key in this._testDoneTimes && key in this._testStartTimes) {
+      var time = this._testDoneTimes[key] - this._testStartTimes[key];
+      message.time = time;
+
+      var slowThreshold = this._getSlowThresholdForTest(key);
+      message.halfSlow = time >= slowThreshold / 2;
+      message.slow = time >= slowThreshold;
+    }
+  }
+
+  this._forwardCall('gotMessage', [testPath, message]);
+};
+
+module.exports = Timer;

lib/suite_runner.js

@@ -27,6 +27,7 @@ var softKill = require('./soft_kill');
 var CombinedReporter = require('./reporter/combined');
 var CancellableReporter = require('./reporter/cancellable');
 var ErrorDetectorReporter = require('./reporter/error_detector');
+var TimerReporter = require('./reporter/timer');
 var TestFailureError = require('./test_failure_error');
 var TimeoutTimer = require('./timeout_timer');
 
@@ -244,7 +245,9 @@ module.exports = function(options) {
   var testInterfacePath = path.resolve(options.interface);
   var errorDetector = new ErrorDetectorReporter();
   var reporter = new CancellableReporter(
-    new CombinedReporter([errorDetector].concat(options.reporters)));
+    new TimerReporter(
+      new CombinedReporter([errorDetector].concat(options.reporters)),
+      slowThreshold));
 
   var cancelled = false;
 

test.js

@@ -38,7 +38,8 @@ var suitePromise = suiterunner({
       new ErrorDetailReporter(process.stdout)
     ],
     parallelism: 8,
-    timeout: 10000
+    timeout: 10000,
+    slowThreshold: 1000
   });
 
 process.on('SIGINT', function() {

test/test_reporter_api.js

@@ -339,7 +339,9 @@ describe('Reporter API', function() {
     });
 
     return when.all([
-      shouldFail(testSuitePromise, function(err) { return err instanceof TestFailureError; }),
+      shouldFail(testSuitePromise, function(err) {
+        return err instanceof TestFailureError;
+      }),
       deferred.promise
     ]);
   });
@@ -356,7 +358,9 @@ describe('Reporter API', function() {
     }));
 
     return when.all([
-      shouldFail(suitePromise),
+      shouldFail(suitePromise, function(err) {
+        return err instanceof TestFailureError;
+      }),
       deferred.promise
     ]);
   });
@@ -395,11 +399,24 @@ describe('Reporter API', function() {
     });
 
     return when.all([
-      shouldFail(suitePromise),
+      shouldFail(suitePromise, function(error) {
+        return error instanceof TestFailureError;
+      }),
       deferred.promise
     ]);
   });
 
+  describe('Test timer', function() {
+    ['time', 'halfSlow', 'slow'].forEach(function(field) {
+      it('should emit finish messages that have ' + field + ' property', function() {
+        return ensureMessages('suite_single_successful_test', [function(testPath, message) {
+          expect(message).property('type').to.be.equal('finish');
+          expect(message).property(field).to.exist;
+        }]);
+      });
+    });
+  });
+
   it('should gracefully handle when the interface takes forever', function() {
     return shouldFail(runTestSuite('suite_neverending_listing'), function(error) {
       return (error instanceof TestFailureError) &&

test/test_timer.js

@@ -0,0 +1,165 @@
+/*
+ * Copyright 2014 Per Eckerdal
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+'use strict';
+
+var EventEmitter = require('events').EventEmitter;
+var expect = require('chai').expect;
+var makeFakeClock = require('./util/fake_clock');
+var OnMessage = require('./util/on_message');
+var Timer = require('../lib/reporter/timer');
+
+describe('Timer reporter', function() {
+  var clock;
+  var messages;
+  var timer;
+  var slowThreshold;
+  beforeEach(function() {
+    clock = makeFakeClock();
+    messages = new EventEmitter();
+    slowThreshold = 1000;
+    timer = new Timer(new OnMessage(messages.emit.bind(messages, 'message')), slowThreshold, clock);
+  });
+
+  it('should require the default slow threshold parameter', function() {
+    expect(function() {
+      new Timer({});
+    }).to.throw(/slow threshold/);
+  });
+
+  describe('Forwarding', function() {
+    ['registrationFailed', 'registerTests', 'done', 'gotMessage'].forEach(function(message) {
+      it('should forward ' + message + ' calls', function(done) {
+        var reporter = {};
+        reporter[message] = function(arg1, arg2) {
+          expect(arg1).to.be.equal('arg1');
+          expect(arg2).to.be.equal('arg2');
+          done();
+        };
+
+        var timer = new Timer(reporter, 0);
+        timer[message]('arg1', 'arg2');
+      });
+    });
+  });
+
+  describe('Time', function() {
+    it('should add time to finish messages', function(done) {
+      messages.on('message', function(path, message) {
+        if (message.type === 'finish') {
+          expect(message).property('time').to.be.equal(100);
+          done();
+        }
+      });
+
+      timer.gotMessage('test', { type: 'start' });
+      clock.step(10);
+      timer.gotMessage('test', { type: 'startedTest' });
+      clock.step(100);
+      timer.gotMessage('test', { type: 'startedAfterHooks' });
+      clock.step(1000);
+      timer.gotMessage('test', { type: 'finish' });
+    });
+
+    it('should use wall clock by default', function(done) {
+      var timer = new Timer(new OnMessage(messages.emit.bind(messages, 'message')), 0);
+      messages.on('message', function(path, message) {
+        if (message.type === 'finish') {
+          expect(message).property('time').to.be.within(90, 150);
+          done();
+        }
+      });
+
+      timer.gotMessage('test', { type: 'start' });
+      timer.gotMessage('test', { type: 'startedTest' });
+      setTimeout(function() {
+        timer.gotMessage('test', { type: 'startedAfterHooks' });
+        timer.gotMessage('test', { type: 'finish' });
+      }, 100);
+    });
+
+    it('should not crash when receiving mismatched finish message', function(done) {
+      messages.on('message', function(path, message) {
+        if (message.type === 'finish') {
+          done();
+        }
+      });
+
+      timer.gotMessage('test', { type: 'finish' });
+    });
+  });
+
+  describe('slow and halfSlow', function() {
+    [true, false].forEach(function(shouldEmitSetSlowThresholdMessage) {
+      it('should not mark fast test as slow or halfSlow' + (shouldEmitSetSlowThresholdMessage ? ' when slow threshold is modified' : ''), function(done) {
+        messages.on('message', function(path, message) {
+          if (message.type === 'finish') {
+            expect(message).property('slow').to.be.false;
+            expect(message).property('halfSlow').to.be.false;
+            done();
+          }
+        });
+
+        timer.gotMessage('test', { type: 'start' });
+        if (shouldEmitSetSlowThresholdMessage) {
+          timer.gotMessage('test', { type: 'setSlowThreshold', value: 2000 });
+        }
+        timer.gotMessage('test', { type: 'startedTest' });
+        clock.step(shouldEmitSetSlowThresholdMessage ? 999 : 499);
+        timer.gotMessage('test', { type: 'startedAfterHooks' });
+        timer.gotMessage('test', { type: 'finish' });
+      });
+
+      it('should not mark half-slow test as halfSlow' + (shouldEmitSetSlowThresholdMessage ? ' when slow threshold is modified' : ''), function(done) {
+        messages.on('message', function(path, message) {
+          if (message.type === 'finish') {
+            expect(message).property('slow').to.be.false;
+            expect(message).property('halfSlow').to.be.true;
+            done();
+          }
+        });
+
+        timer.gotMessage('test', { type: 'start' });
+        timer.gotMessage('test', { type: 'startedTest' });
+        if (shouldEmitSetSlowThresholdMessage) {
+          timer.gotMessage('test', { type: 'setSlowThreshold', value: 500 });
+        }
+        clock.step(shouldEmitSetSlowThresholdMessage ? 250 : 500);
+        timer.gotMessage('test', { type: 'startedAfterHooks' });
+        timer.gotMessage('test', { type: 'finish' });
+      });
+
+      it('should not mark slow test as slow and halfSlow' + (shouldEmitSetSlowThresholdMessage ? ' when slow threshold is modified' : ''), function(done) {
+        messages.on('message', function(path, message) {
+          if (message.type === 'finish') {
+            expect(message).property('slow').to.be.true;
+            expect(message).property('halfSlow').to.be.true;
+            done();
+          }
+        });
+
+        timer.gotMessage('test', { type: 'start' });
+        if (shouldEmitSetSlowThresholdMessage) {
+          timer.gotMessage('test', { type: 'setSlowThreshold', value: 2000 });
+        }
+        timer.gotMessage('test', { type: 'startedTest' });
+        clock.step(shouldEmitSetSlowThresholdMessage ? 2000 : 1000);
+        timer.gotMessage('test', { type: 'startedAfterHooks' });
+        timer.gotMessage('test', { type: 'finish' });
+      });
+    });
+  });
+});