Close #30 PR: Output test execution time. Fixes #14

Author: vdemedes

index.js

@@ -1,4 +1,5 @@
 'use strict';
+var prettyMs = require('pretty-ms');
 var chalk = require('chalk');
 var figures = require('figures');
 var Squeak = require('squeak');
@@ -17,13 +18,27 @@ log.type('error', {
 	prefix: figures.cross
 });
 
-function test(err, title) {
+function test(err, title, duration) {
 	if (err) {
 		log.error(title, chalk.red(err.message));
 		return;
 	}
 
-	log.success(title);
+	// format a time spent in the test
+	var timeSpent = '';
+
+	// display duration only over a threshold
+	var threshold = 100;
+
+	if (duration > threshold) {
+		var formattedDuration = prettyMs(duration, {
+			secDecimalDigits: 2
+		});
+
+		timeSpent = chalk.gray.dim(' (' + formattedDuration + ')');
+	}
+
+	log.success(title + timeSpent);
 }
 
 function stack(results) {

lib/runner.js

@@ -36,35 +36,37 @@ Runner.prototype.addSerialTest = function (title, cb) {
 
 Runner.prototype.concurrent = function (cb) {
 	each(this.tests.concurrent, function (test, i, next) {
-		test.run(function (err) {
+		test.run(function (err, duration) {
 			if (err) {
 				this.stats.failCount++;
 			}
 
 			this.results.push({
+				duration: duration,
 				title: test.title,
 				error: err
 			});
 
-			this.emit('test', err, test.title);
+			this.emit('test', err, test.title, duration);
 			next();
 		}.bind(this));
 	}.bind(this), cb);
 };
 
 Runner.prototype.serial = function (cb) {
 	eachSerial(this.tests.serial, function (test, next) {
-		test.run(function (err) {
+		test.run(function (err, duration) {
 			if (err) {
 				this.stats.failCount++;
 			}
 
 			this.results.push({
+				duration: duration,
 				title: test.title,
 				error: err
 			});
 
-			this.emit('test', err, test.title);
+			this.emit('test', err, test.title, duration);
 			next();
 		}.bind(this));
 	}.bind(this), cb);

lib/test.js

@@ -21,6 +21,12 @@ function Test(title, fn) {
 	this.fn = fn;
 	this.assertCount = 0;
 	this.planCount = null;
+	this.duration = null;
+
+	// store the time point
+	// before test execution
+	// to calculate the total time spent in test
+	this._timeStart = null;
 }
 
 util.inherits(Test, EventEmitter);
@@ -67,6 +73,8 @@ Test.prototype.run = function (cb) {
 		this.exit();
 	}
 
+	this._timeStart = Date.now();
+
 	try {
 		var ret = this.fn(this);
 
@@ -98,6 +106,9 @@ Test.prototype.end = function () {
 };
 
 Test.prototype.exit = function () {
+	// calculate total time spent in test
+	this.duration = Date.now() - this._timeStart;
+
 	if (this.planCount !== null && this.planCount !== this.assertCount) {
 		this.assertError = new assert.AssertionError({
 			actual: this.assertCount,
@@ -113,7 +124,7 @@ Test.prototype.exit = function () {
 		this.ended = true;
 
 		setImmediate(function () {
-			this.cb(this.assertError);
+			this.cb(this.assertError, this.duration);
 		}.bind(this));
 	}
 };

package.json

@@ -54,6 +54,7 @@
     "globby": "^2.0.0",
     "meow": "^3.3.0",
     "plur": "^2.0.0",
+    "pretty-ms": "^2.0.0",
     "squeak": "^1.2.0",
     "update-notifier": "^0.5.0"
   },

test/test.js

@@ -343,3 +343,21 @@ test('promise support - reject', function (t) {
 		t.end();
 	});
 });
+
+test('record test duration', function (t) {
+	var avaTest;
+
+	ava(function (a) {
+		avaTest = a;
+
+		a.plan(1);
+
+		setTimeout(function () {
+			a.true(true);
+		}, 1234);
+	}).run(function (err) {
+		t.false(err);
+		t.true(avaTest.duration >= 1234);
+		t.end();
+	});
+});