Skip to content

Commit

Permalink
console: display timeEnd with suitable time unit
Browse files Browse the repository at this point in the history
When timeEnd function is called, display result with a suitable
time unit instead of a big amount of milliseconds.

Refs: #29099

PR-URL: #29251
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
  • Loading branch information
Xstoudi authored and BridgeAR committed Sep 3, 2019
1 parent 8a93b63 commit fdfde05
Show file tree
Hide file tree
Showing 3 changed files with 60 additions and 19 deletions.
32 changes: 29 additions & 3 deletions lib/internal/console/constructor.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -518,14 +522,35 @@ 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: %sms', label, ms.toFixed(3));
self.log('%s: %s', label, formatted);
} else {
self.log('%s: %sms', label, ms.toFixed(3), ...data);
self.log('%s: %s', label, formatted, ...data);
}
return true;
}

function formatTime(ms) {
let value = ms;
let unit = 'ms';

if (ms >= kHour) {
value = ms / kHour;
unit = 'h';
} else if (ms >= kMinute) {
value = ms / kMinute;
unit = 'min';
} else if (ms >= kSecond) {
value = ms / kSecond;
unit = 's';
}

return value.toFixed(3) + unit;
}

const keyKey = 'Key';
const valuesKey = 'Values';
const indexKey = '(index)';
Expand All @@ -547,5 +572,6 @@ Console.prototype.groupCollapsed = Console.prototype.group;
module.exports = {
Console,
kBindStreamsLazy,
kBindProperties
kBindProperties,
formatTime // exported for tests
};
15 changes: 15 additions & 0 deletions test/parallel/test-console-formatTime.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
'use strict';
// Flags: --expose-internals
require('../common');
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, '100.000ms');
assert.strictEqual(test2, '1.500s');
assert.strictEqual(test3, '1.005min');
assert.strictEqual(test4, '1.111h');
32 changes: 16 additions & 16 deletions test/parallel/test-console.js
Original file line number Diff line number Diff line change
Expand Up @@ -246,24 +246,24 @@ 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);
Expand Down

0 comments on commit fdfde05

Please sign in to comment.