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: implement timeLog method #21312

Closed
wants to merge 1 commit into from
Closed

console: implement timeLog method #21312

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 19 additions & 0 deletions doc/api/console.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -413,6 +413,25 @@ console.timeEnd('100-elements');
// prints 100-elements: 225.438ms
```

### console.timeLog([label][, ...data])
<!-- YAML
added: REPLACEME
-->
* `label` {string} **Default:** `'default'`
* `...data` {any}

For a timer that was previously started by calling [`console.time()`][], prints
the elapsed time and other `data` arguments to `stdout`:

```js
console.time('process');
const value = expensiveProcess1(); // Returns 42
console.timeLog('process', value);
// Prints "process: 365.227ms 42".
doExpensiveProcess2(value);
console.timeEnd('process');
Copy link
Member

Choose a reason for hiding this comment

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

This will print a warning about no process label, right?

Copy link
Member Author

@targos targos Jun 18, 2018 •
edited
Loading

Choose a reason for hiding this comment

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

It's not supposed to. timeLog shouldn't clear the timer.

```

### console.trace([message][, ...args])
<!-- YAML
added: v0.1.104
Expand Down
28 changes: 22 additions & 6 deletions lib/console.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -235,18 +235,34 @@ Console.prototype.time = function time(label = 'default') {
};

Console.prototype.timeEnd = function timeEnd(label = 'default') {
const hasWarned = timeLogImpl(this, 'timeEnd', label);
if (!hasWarned) {
this._times.delete(label);
}
};

Console.prototype.timeLog = function timeLog(label, ...data) {
timeLogImpl(this, 'timeLog', label, data);
};

// Returns true if label was not found
function timeLogImpl(self, name, label = 'default', data) {
// Coerces everything other than Symbol to a string
label = `${label}`;
const time = this._times.get(label);
const time = self._times.get(label);
if (!time) {
process.emitWarning(`No such label '${label}' for console.timeEnd()`);
return;
process.emitWarning(`No such label '${label}' for console.${name}()`);
return true;
}
const duration = process.hrtime(time);
const ms = duration[0] * 1000 + duration[1] / 1e6;
this.log('%s: %sms', label, ms.toFixed(3));
this._times.delete(label);
};
if (data === undefined) {
self.log('%s: %sms', label, ms.toFixed(3));
} else {
self.log('%s: %sms', label, ms.toFixed(3), ...data);
}
return false;
}

Console.prototype.trace = function trace(...args) {
const err = {
Expand Down
34 changes: 25 additions & 9 deletions test/parallel/test-console.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,11 +31,18 @@ if (common.isMainThread) {
assert.strictEqual(typeof process.stdout.fd, 'number');
assert.strictEqual(typeof process.stderr.fd, 'number');
}
process.once('warning', common.mustCall((warning) => {
assert(/no such label/.test(warning.message));
}));

console.timeEnd('no such label');
common.expectWarning(
'Warning',
[
['No such label \'nolabel\' for console.timeEnd()', common.noWarnCode],
['No such label \'nolabel\' for console.timeLog()', common.noWarnCode],
['Label \'test\' already exists for console.time()', common.noWarnCode]
]
);

console.timeEnd('nolabel');
console.timeLog('nolabel');

console.time('label');
console.timeEnd('label');
Expand Down Expand Up @@ -144,15 +151,16 @@ console.timeEnd(NaN);
console.time('test');
const time = console._times.get('test');
setTimeout(() => {
common.expectWarning(
'Warning',
'Label \'test\' already exists for console.time()',
common.noWarnCode);
console.time('test');
assert.deepStrictEqual(console._times.get('test'), time);
console.timeEnd('test');
}, 1);

console.time('log1');
console.timeLog('log1');
console.timeLog('log1', 'test');
console.timeLog('log1', {}, [1, 2, 3]);
console.timeEnd('log1');

console.assert(false, '%s should', 'console.assert', 'not throw');
assert.strictEqual(errStrings[errStrings.length - 1],
Expand Down Expand Up @@ -219,6 +227,14 @@ 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()));

// Make sure that we checked all strings
assert.strictEqual(strings.length, 0);

assert.strictEqual(errStrings.shift().split('\n').shift(),
'Trace: This is a {"formatted":"trace"} 10 foo');

Expand All @@ -229,6 +245,6 @@ common.hijackStderr(common.mustCall(function(data) {

// stderr.write will catch sync error, so use `process.nextTick` here
process.nextTick(function() {
assert.strictEqual(data.includes('no such label'), true);
assert.strictEqual(data.includes('nolabel'), true);
});
}));