Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

console: display timeEnd with suitable time unit #29251

Closed
wants to merge 9 commits into from
Closed
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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i think we should always show the milliseconds

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not convinced. even in case it's a few seconds, I don't think we need more than millisecond precision.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if we don't include milliseconds can we remove the toFixed?

Copy link
Contributor Author

@Xstoudi Xstoudi Aug 23, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

time and timeEnd couple seems to be here to allow developers to get an idea of which time scale does a part of their code take to run. I think it's usefull to know whether the code takes 500ms, 1, 1min or 1h to run but I don't see any case where the difference between 1h and 1.0000000000000001h is important. People that need high precision can still use process.hrtime.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am in favor of changing the representation in general but I think it would have been good to keep the milliseconds. I think it would have been ideal to visualize it as: n1h, n2m, n3s and n4ms (n1 - n4 as value) while each leading part would be optional as long as all former ones are zero. Right now you have to calculate in a fraction of an hour or minutes and that is not very intuitive.

}

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()));
Xstoudi marked this conversation as resolved.
Show resolved Hide resolved
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