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.

Sign up for GitHub

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

Jump to bottom

console: display timeEnd with suitable time unit #29251

Closed
wants to merge 9 commits into from
Closed

console: display timeEnd with suitable time unit #29251

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
b00bdf6
console: display timeEnd with suitable time unit
Xstoudi Aug 21, 2019
c4eb2d6
console: extract formatTime and export it for test
Xstoudi Aug 21, 2019
dc97305
test: adapt tests
Xstoudi Aug 21, 2019
106bbd4
console: don't trim formatTime value before returning it
Xstoudi Aug 21, 2019
510ef86
test: adapt formatTime tests to previous commit
Xstoudi Aug 21, 2019
57bbc6c
console: fix linter
Xstoudi Aug 21, 2019
c5063d0
test: fix linter
Xstoudi Aug 21, 2019
368e5d7
console: move magic numbers to constants
Xstoudi Aug 22, 2019
da4e02f
test: add blank line
Xstoudi Aug 22, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
32 changes: 29 additions & 3 deletions lib/internal/console/constructor.js
View file
Open in desktop
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 •
edited

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
View file
Open in desktop
@@ -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
View file
Open in desktop
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