From 89c3537cb9dcae121807f249e8c2e85709cf2e32 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 12:18:57 +0300 Subject: [PATCH 01/11] calculate total test duration using process.hrtime() --- lib/test.js | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/lib/test.js b/lib/test.js index 962f7bf48..f37942780 100644 --- a/lib/test.js +++ b/lib/test.js @@ -21,6 +21,12 @@ function Test(title, fn) { this.fn = fn; this.assertCount = 0; this.planCount = null; + + // store the time point + // before test execution + // to pass it to process.hrtime() + // and calculate the total time spent in test + this._timeStart = 0; } util.inherits(Test, EventEmitter); @@ -67,6 +73,8 @@ Test.prototype.run = function (cb) { this.exit(); } + this._timeStart = process.hrtime(); + try { var ret = this.fn(this); @@ -98,6 +106,9 @@ Test.prototype.end = function () { }; Test.prototype.exit = function () { + // calculate total time spent in test + var duration = process.hrtime(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, duration); }.bind(this)); } }; From 8833de625420f3b69a2d2913df0ca9a8918f794f Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 12:19:50 +0300 Subject: [PATCH 02/11] store and emit test duration --- lib/runner.js | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/lib/runner.js b/lib/runner.js index dd33bfc59..6df9b914c 100644 --- a/lib/runner.js +++ b/lib/runner.js @@ -36,17 +36,18 @@ 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); @@ -54,17 +55,18 @@ Runner.prototype.concurrent = function (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); From a3492c36fa2fd91f0ab63231be7b9e65aec2d961 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 12:20:11 +0300 Subject: [PATCH 03/11] output the duration of successful tests --- index.js | 5 +++-- package.json | 1 + 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/index.js b/index.js index 0c7d45e2b..83fe96a62 100644 --- a/index.js +++ b/index.js @@ -1,4 +1,5 @@ 'use strict'; +var hrtime = require('pretty-hrtime'); var chalk = require('chalk'); var figures = require('figures'); var Squeak = require('squeak'); @@ -17,13 +18,13 @@ 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); + log.success(title + ' (' + hrtime(duration) + ')'); } function stack(results) { diff --git a/package.json b/package.json index 17a18e310..99a09eacb 100644 --- a/package.json +++ b/package.json @@ -54,6 +54,7 @@ "globby": "^2.0.0", "meow": "^3.3.0", "plur": "^2.0.0", + "pretty-hrtime": "^1.0.0", "squeak": "^1.2.0", "update-notifier": "^0.5.0" }, From 6abe83ad9206d00b3bc3c5250f7a5e5b53440d27 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 13:19:20 +0300 Subject: [PATCH 04/11] dim the lights a little --- index.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/index.js b/index.js index 83fe96a62..b02e8e715 100644 --- a/index.js +++ b/index.js @@ -24,7 +24,7 @@ function test(err, title, duration) { return; } - log.success(title + ' (' + hrtime(duration) + ')'); + log.success(title + ' ' + chalk.dim('(' + hrtime(duration) + ')')); } function stack(results) { From 9838428babee95da49d4ae96b134d615d5d498ee Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 13:24:39 +0300 Subject: [PATCH 05/11] Measure time using Date.now() instead of process.hrtime() Duration measured in nanoseconds does not give any valuable information to the developer. It makes sense to display time only for long-running tests, above some threshold. Also, process.hrtime() is not available in browsers, so it would need replacement anyway. --- index.js | 4 ++-- lib/test.js | 7 +++---- package.json | 2 +- 3 files changed, 6 insertions(+), 7 deletions(-) diff --git a/index.js b/index.js index b02e8e715..87467e4a7 100644 --- a/index.js +++ b/index.js @@ -1,5 +1,5 @@ 'use strict'; -var hrtime = require('pretty-hrtime'); +var prettyMs = require('pretty-ms'); var chalk = require('chalk'); var figures = require('figures'); var Squeak = require('squeak'); @@ -24,7 +24,7 @@ function test(err, title, duration) { return; } - log.success(title + ' ' + chalk.dim('(' + hrtime(duration) + ')')); + log.success(title + ' ' + chalk.dim('(' + prettyMs(duration) + ')')); } function stack(results) { diff --git a/lib/test.js b/lib/test.js index f37942780..a896b2c3d 100644 --- a/lib/test.js +++ b/lib/test.js @@ -24,8 +24,7 @@ function Test(title, fn) { // store the time point // before test execution - // to pass it to process.hrtime() - // and calculate the total time spent in test + // to calculate the total time spent in test this._timeStart = 0; } @@ -73,7 +72,7 @@ Test.prototype.run = function (cb) { this.exit(); } - this._timeStart = process.hrtime(); + this._timeStart = Date.now(); try { var ret = this.fn(this); @@ -107,7 +106,7 @@ Test.prototype.end = function () { Test.prototype.exit = function () { // calculate total time spent in test - var duration = process.hrtime(this._timeStart); + var duration = Date.now() - this._timeStart; if (this.planCount !== null && this.planCount !== this.assertCount) { this.assertError = new assert.AssertionError({ diff --git a/package.json b/package.json index 99a09eacb..70ec469ef 100644 --- a/package.json +++ b/package.json @@ -54,7 +54,7 @@ "globby": "^2.0.0", "meow": "^3.3.0", "plur": "^2.0.0", - "pretty-hrtime": "^1.0.0", + "pretty-ms": "^2.0.0", "squeak": "^1.2.0", "update-notifier": "^0.5.0" }, From 2791234f08d8d474ae7558522e366b253a741443 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 13:31:52 +0300 Subject: [PATCH 06/11] display test duration only if a threshold is reached --- index.js | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/index.js b/index.js index 87467e4a7..79c907dee 100644 --- a/index.js +++ b/index.js @@ -24,7 +24,17 @@ function test(err, title, duration) { return; } - log.success(title + ' ' + chalk.dim('(' + prettyMs(duration) + ')')); + // format a time spent in the test + var timeSpent = ''; + + // display duration only over a threshold + var threshold = 100; + + if (duration > threshold) { + timeSpent = chalk.dim('(' + prettyMs(duration) + ')'); + } + + log.success(title + ' ' + timeSpent); } function stack(results) { From edca8d6449bc055bcdf43f142b1d498b0af385e2 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 14:08:43 +0300 Subject: [PATCH 07/11] display test duration using chalk.gray.dim, because chalk.dim doesn't work everywhere --- index.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/index.js b/index.js index 79c907dee..dc465eb98 100644 --- a/index.js +++ b/index.js @@ -31,10 +31,10 @@ function test(err, title, duration) { var threshold = 100; if (duration > threshold) { - timeSpent = chalk.dim('(' + prettyMs(duration) + ')'); + timeSpent = chalk.gray.dim(' (' + prettyMs(duration) + ')'); } - log.success(title + ' ' + timeSpent); + log.success(title + timeSpent); } function stack(results) { From 306a49148493c558495447e06db3d3b7b9f1caf6 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 14:13:17 +0300 Subject: [PATCH 08/11] display 2 decimal digits for test duration --- index.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/index.js b/index.js index dc465eb98..81a564d3e 100644 --- a/index.js +++ b/index.js @@ -31,7 +31,9 @@ function test(err, title, duration) { var threshold = 100; if (duration > threshold) { - timeSpent = chalk.gray.dim(' (' + prettyMs(duration) + ')'); + var formattedDuration = prettyMs(duration, { secDecimalDigits: 2 }); + + timeSpent = chalk.gray.dim(' (' + formattedDuration + ')'); } log.success(title + timeSpent); From ca9426cc9f3d864d8cb9cf80b1bc36557dff3fed Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 14:14:33 +0300 Subject: [PATCH 09/11] fix code formatting to satisfy xo requirements --- index.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/index.js b/index.js index 81a564d3e..070c3458b 100644 --- a/index.js +++ b/index.js @@ -31,7 +31,9 @@ function test(err, title, duration) { var threshold = 100; if (duration > threshold) { - var formattedDuration = prettyMs(duration, { secDecimalDigits: 2 }); + var formattedDuration = prettyMs(duration, { + secDecimalDigits: 2 + }); timeSpent = chalk.gray.dim(' (' + formattedDuration + ')'); } From 502245cb0464c4fb4eb7ca01d0fe9cff73b006cd Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 14:37:15 +0300 Subject: [PATCH 10/11] store test duration in Test#duration property --- lib/test.js | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/lib/test.js b/lib/test.js index a896b2c3d..8a21d2eff 100644 --- a/lib/test.js +++ b/lib/test.js @@ -21,11 +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 = 0; + this._timeStart = null; } util.inherits(Test, EventEmitter); @@ -106,7 +107,7 @@ Test.prototype.end = function () { Test.prototype.exit = function () { // calculate total time spent in test - var duration = Date.now() - this._timeStart; + this.duration = Date.now() - this._timeStart; if (this.planCount !== null && this.planCount !== this.assertCount) { this.assertError = new assert.AssertionError({ @@ -123,7 +124,7 @@ Test.prototype.exit = function () { this.ended = true; setImmediate(function () { - this.cb(this.assertError, duration); + this.cb(this.assertError, this.duration); }.bind(this)); } }; From 98f4cb9df7b867a765674085ebc432d8a2713f71 Mon Sep 17 00:00:00 2001 From: vdemedes Date: Tue, 1 Sep 2015 14:37:29 +0300 Subject: [PATCH 11/11] add a test for measuring duration --- test/test.js | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/test/test.js b/test/test.js index fbec14a6d..a746588c7 100644 --- a/test/test.js +++ b/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(); + }); +});