From b00bdf6eb21f74067a65804a067930684feebb7d Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 18:31:06 +0200 Subject: [PATCH 1/9] console: display timeEnd with suitable time unit When timeEnd function is called, display result with a suitable time unit instead of a big amount of milliseconds. Refs: https://github.com/nodejs/node/issues/29099 --- lib/internal/console/constructor.js | 19 +++++++++++++++++-- 1 file changed, 17 insertions(+), 2 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index a618457124c877..b410f0b6e59938 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -518,10 +518,25 @@ function timeLogImpl(self, name, label, data) { } const duration = process.hrtime(time); const ms = duration[0] * 1000 + duration[1] / 1e6; + + let value = ms; + let unit = 'ms'; + + if (ms >= 3600000) { + value = ms / 3600000; + unit = 'h'; + } else if (ms >= 60000) { + value = ms / 60000; + unit = 'min'; + } else if (ms >= 1000) { + value = ms / 1000; + unit = 's'; + } + if (data === undefined) { - self.log('%s: %sms', label, ms.toFixed(3)); + self.log('%s: %s%s', label, value.toFixed(3), unit); } else { - self.log('%s: %sms', label, ms.toFixed(3), ...data); + self.log('%s: %s%s', label, value.toFixed(3), unit, ...data); } return true; } From c4eb2d66339310215c5659104500705276b43224 Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 21:01:56 +0200 Subject: [PATCH 2/9] console: extract formatTime and export it for test Extract the format time part to be able to test it. --- lib/internal/console/constructor.js | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index b410f0b6e59938..d08fb803bfb5db 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -519,6 +519,17 @@ function timeLogImpl(self, name, label, data) { const duration = process.hrtime(time); const ms = duration[0] * 1000 + duration[1] / 1e6; + const formatted = formatTime(ms); + + if (data === undefined) { + self.log('%s: %s', label, formatted); + } else { + self.log('%s: %s', label, formatted, ...data); + } + return true; +} + +function formatTime(ms) { let value = ms; let unit = 'ms'; @@ -533,12 +544,7 @@ function timeLogImpl(self, name, label, data) { unit = 's'; } - if (data === undefined) { - self.log('%s: %s%s', label, value.toFixed(3), unit); - } else { - self.log('%s: %s%s', label, value.toFixed(3), unit, ...data); - } - return true; + return value.toFixed(3) * 1 + unit; } const keyKey = 'Key'; @@ -562,5 +568,6 @@ Console.prototype.groupCollapsed = Console.prototype.group; module.exports = { Console, kBindStreamsLazy, - kBindProperties + kBindProperties, + formatTime // exported for tests }; From dc9730540c282860af0bbe0bcb08509f37393bdf Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 21:03:43 +0200 Subject: [PATCH 3/9] test: adapt tests Change regexp of test-console to accept other possible units and create test for formatTime --- test/parallel/test-console-formatTime.js | 13 ++++++++++ test/parallel/test-console.js | 33 ++++++++++++------------ 2 files changed, 29 insertions(+), 17 deletions(-) create mode 100644 test/parallel/test-console-formatTime.js diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js new file mode 100644 index 00000000000000..286e1e8dbdc985 --- /dev/null +++ b/test/parallel/test-console-formatTime.js @@ -0,0 +1,13 @@ +// Flags: --expose-internals +const { formatTime } = require('internal/console/constructor'); +const assert = require('assert'); + +const test1 = formatTime(100); +const test2 = formatTime(1500); +const test3 = formatTime(60300); +const test4 = formatTime(4000000); + +assert.strictEqual(test1, '100ms'); +assert.strictEqual(test2, '1.5s'); +assert.strictEqual(test3, '1.005min') +assert.strictEqual(test4, '1.111h') \ No newline at end of file diff --git a/test/parallel/test-console.js b/test/parallel/test-console.js index e2c5291d915c1d..7af0a1141b2548 100644 --- a/test/parallel/test-console.js +++ b/test/parallel/test-console.js @@ -245,25 +245,24 @@ assert.strictEqual(strings.shift(), 'inspect inspect\n'); assert.ok(strings[0].includes('foo: { bar: { baz:')); assert.ok(strings[0].includes('quux')); assert.ok(strings.shift().includes('quux: true')); - -assert.ok(/^label: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^__proto__: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^constructor: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^hasOwnProperty: \d+\.\d{3}ms$/.test(strings.shift().trim())); +assert.ok(/^label: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^__proto__: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^constructor: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^hasOwnProperty: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); // Verify that console.time() coerces label values to strings as expected -assert.ok(/^: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^\[object Object\]: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^\[object Object\]: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^null: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^default: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^default: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^NaN: \d+\.\d{3}ms$/.test(strings.shift().trim())); - -assert.ok(/^log1: \d+\.\d{3}ms$/.test(strings.shift().trim())); -assert.ok(/^log1: \d+\.\d{3}ms test$/.test(strings.shift().trim())); -assert.ok(/^log1: \d+\.\d{3}ms {} \[ 1, 2, 3 ]$/.test(strings.shift().trim())); -assert.ok(/^log1: \d+\.\d{3}ms$/.test(strings.shift().trim())); +assert.ok(/^: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^\[object Object\]: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^\[object Object\]: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^null: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^default: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^default: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^NaN: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); + +assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); +assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h) test$/.test(strings.shift().trim())); +assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h) {} \[ 1, 2, 3 ]$/.test(strings.shift().trim())); +assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); // Make sure that we checked all strings assert.strictEqual(strings.length, 0); From 106bbd48e2dfa8bb96aedd82101a042729864c11 Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 21:46:44 +0200 Subject: [PATCH 4/9] console: don't trim formatTime value before returning it Tests in test-console.js expect 3 floating points. --- lib/internal/console/constructor.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index d08fb803bfb5db..feeaa2b45ad7b7 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -544,7 +544,7 @@ function formatTime(ms) { unit = 's'; } - return value.toFixed(3) * 1 + unit; + return value.toFixed(3) + unit; } const keyKey = 'Key'; From 510ef867ee760d2db1b0e6f2002eb192ab62d5ce Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 21:49:12 +0200 Subject: [PATCH 5/9] test: adapt formatTime tests to previous commit Assert that returnes value as 3 floating points --- test/parallel/test-console-formatTime.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js index 286e1e8dbdc985..e96bfa2fe64728 100644 --- a/test/parallel/test-console-formatTime.js +++ b/test/parallel/test-console-formatTime.js @@ -7,7 +7,7 @@ const test2 = formatTime(1500); const test3 = formatTime(60300); const test4 = formatTime(4000000); -assert.strictEqual(test1, '100ms'); -assert.strictEqual(test2, '1.5s'); +assert.strictEqual(test1, '100.000ms'); +assert.strictEqual(test2, '1.500s'); assert.strictEqual(test3, '1.005min') assert.strictEqual(test4, '1.111h') \ No newline at end of file From 57bbc6c077b3af1517f0aaa169bf7ff05ce2cbf0 Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 23:04:09 +0200 Subject: [PATCH 6/9] console: fix linter Edit the file to fulfill the linter requirements --- lib/internal/console/constructor.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index feeaa2b45ad7b7..1038ac796e1841 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -520,7 +520,7 @@ function timeLogImpl(self, name, label, data) { const ms = duration[0] * 1000 + duration[1] / 1e6; const formatted = formatTime(ms); - + if (data === undefined) { self.log('%s: %s', label, formatted); } else { From c5063d00e51d2cd2c0aae162df815483ba8a1498 Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Wed, 21 Aug 2019 23:04:57 +0200 Subject: [PATCH 7/9] test: fix linter Edit the file to fulfill the linter requirements --- test/parallel/test-console-formatTime.js | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js index e96bfa2fe64728..aa5f7ec7aa4bf2 100644 --- a/test/parallel/test-console-formatTime.js +++ b/test/parallel/test-console-formatTime.js @@ -1,4 +1,6 @@ +'use strict'; // Flags: --expose-internals +require('../common'); const { formatTime } = require('internal/console/constructor'); const assert = require('assert'); @@ -9,5 +11,5 @@ const test4 = formatTime(4000000); assert.strictEqual(test1, '100.000ms'); assert.strictEqual(test2, '1.500s'); -assert.strictEqual(test3, '1.005min') -assert.strictEqual(test4, '1.111h') \ No newline at end of file +assert.strictEqual(test3, '1.005min'); +assert.strictEqual(test4, '1.111h'); From 368e5d7d3e1609ac5e85cf9bc7ab29a6ca10ee44 Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Thu, 22 Aug 2019 13:09:57 +0200 Subject: [PATCH 8/9] console: move magic numbers to constants Hour, minute and second equivalent in ms are now constants. --- lib/internal/console/constructor.js | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 1038ac796e1841..554323d9e30c1d 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -32,6 +32,10 @@ const kTraceBegin = 'b'.charCodeAt(0); const kTraceEnd = 'e'.charCodeAt(0); const kTraceInstant = 'n'.charCodeAt(0); +const kSecond = 1000; +const kMinute = 60 * kSecond; +const kHour = 60 * kMinute; + const { isArray: ArrayIsArray, from: ArrayFrom, @@ -533,14 +537,14 @@ function formatTime(ms) { let value = ms; let unit = 'ms'; - if (ms >= 3600000) { - value = ms / 3600000; + if (ms >= kHour) { + value = ms / kHour; unit = 'h'; - } else if (ms >= 60000) { - value = ms / 60000; + } else if (ms >= kMinute) { + value = ms / kMinute; unit = 'min'; - } else if (ms >= 1000) { - value = ms / 1000; + } else if (ms >= kSecond) { + value = ms / kSecond; unit = 's'; } From da4e02f228694907b5c69ab096847ec88a7ff951 Mon Sep 17 00:00:00 2001 From: Xavier Stouder Date: Thu, 22 Aug 2019 13:20:41 +0200 Subject: [PATCH 9/9] test: add blank line --- test/parallel/test-console.js | 1 + 1 file changed, 1 insertion(+) diff --git a/test/parallel/test-console.js b/test/parallel/test-console.js index 7af0a1141b2548..1d76c42edc082e 100644 --- a/test/parallel/test-console.js +++ b/test/parallel/test-console.js @@ -245,6 +245,7 @@ assert.strictEqual(strings.shift(), 'inspect inspect\n'); assert.ok(strings[0].includes('foo: { bar: { baz:')); assert.ok(strings[0].includes('quux')); assert.ok(strings.shift().includes('quux: true')); + assert.ok(/^label: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); assert.ok(/^__proto__: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim())); assert.ok(/^constructor: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));