Skip to content

Commit

Permalink
console: add trace-events for time and count
Browse files Browse the repository at this point in the history
Add the `node.console` trace event category to capture
`console.count()`, `console.countReset()`, `console.time()`,
`console.timeLog()`, and `console.timeEnd()` to the trace
event log.

PR-URL: #23703
Backport-PR-URL: #28840
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
  • Loading branch information
jasnell authored and BethGriggs committed Mar 9, 2020
1 parent 47046aa commit b164a2e
Show file tree
Hide file tree
Showing 4 changed files with 78 additions and 2 deletions.
2 changes: 2 additions & 0 deletions doc/api/tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,8 @@ The available categories are:
The [`async_hooks`] events have a unique `asyncId` and a special `triggerId`
`triggerAsyncId` property.
* `node.bootstrap` - Enables capture of Node.js bootstrap milestones.
* `node.console` - Enables capture of `console.time()` and `console.count()`
output.
* `node.fs.sync` - Enables capture of trace data for file system sync methods.
* `node.perf` - Enables capture of [Performance API] measurements.
* `node.perf.usertiming` - Enables capture of only Performance API User Timing
Expand Down
12 changes: 12 additions & 0 deletions lib/console.js
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@

'use strict';

const { trace } = internalBinding('trace_events');
const {
isStackOverflowError,
codes: {
Expand All @@ -37,6 +38,12 @@ const {
} = util.types;
const kCounts = Symbol('counts');

const kTraceConsoleCategory = 'node,node.console';
const kTraceCount = 'C'.charCodeAt(0);
const kTraceBegin = 'b'.charCodeAt(0);
const kTraceEnd = 'e'.charCodeAt(0);
const kTraceInstant = 'n'.charCodeAt(0);

const {
keys: ObjectKeys,
values: ObjectValues,
Expand Down Expand Up @@ -230,13 +237,15 @@ Console.prototype.dir = function dir(object, options) {
Console.prototype.time = function time(label = 'default') {
// Coerces everything other than Symbol to a string
label = `${label}`;
trace(kTraceBegin, kTraceConsoleCategory, `time::${label}`, 0);
this._times.set(label, process.hrtime());
};

Console.prototype.timeEnd = function timeEnd(label = 'default') {
// Coerces everything other than Symbol to a string
label = `${label}`;
const hasWarned = timeLogImpl(this, 'timeEnd', label);
trace(kTraceEnd, kTraceConsoleCategory, `time::${label}`, 0);
if (!hasWarned) {
this._times.delete(label);
}
Expand All @@ -246,6 +255,7 @@ Console.prototype.timeLog = function timeLog(label, ...data) {
// Coerces everything other than Symbol to a string
label = `${label}`;
timeLogImpl(this, 'timeLog', label, data);
trace(kTraceInstant, kTraceConsoleCategory, `time::${label}`, 0);
};

// Returns true if label was not found
Expand Down Expand Up @@ -306,6 +316,7 @@ Console.prototype.count = function count(label = 'default') {
else
count++;
counts.set(label, count);
trace(kTraceCount, kTraceConsoleCategory, `count::${label}`, 0, count);
this.log(`${label}: ${count}`);
};

Expand All @@ -315,6 +326,7 @@ Console.prototype.count = function count(label = 'default') {
// the counter from being a memory leak.
Console.prototype.countReset = function countReset(label = 'default') {
const counts = this[kCounts];
trace(kTraceCount, kTraceConsoleCategory, `count::${label}`, 0, 0);
counts.delete(`${label}`);
};

Expand Down
4 changes: 2 additions & 2 deletions test/parallel/test-bootstrap-modules.js
Original file line number Diff line number Diff line change
Expand Up @@ -11,5 +11,5 @@ const list = process.moduleLoadList.slice();

const assert = require('assert');

assert(list.length <= 82,
`Expected <= 82 elements in moduleLoadLists, got ${list.length}`);
assert(list.length <= 83,
`Expected <= 83 elements in moduleLoadLists, got ${list.length}`);
62 changes: 62 additions & 0 deletions test/parallel/test-trace-events-console.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,62 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const cp = require('child_process');
const path = require('path');
const fs = require('fs');
const tmpdir = require('../common/tmpdir');

// Tests that node.console trace events for counters and time methods are
// emitted as expected.

const names = [
'time::foo',
'count::bar'
];
const expectedCounts = [ 1, 2, 0 ];
const expectedTimeTypes = [ 'b', 'n', 'e' ];

if (process.argv[2] === 'child') {
// The following console outputs exercise the test, causing node.console
// trace events to be emitted for the counter and time calls.
console.count('bar');
console.count('bar');
console.countReset('bar');
console.time('foo');
setImmediate(() => {
console.timeLog('foo');
setImmediate(() => {
console.timeEnd('foo');
});
});
} else {
tmpdir.refresh();

const proc = cp.fork(__filename,
[ 'child' ], {
cwd: tmpdir.path,
execArgv: [
'--trace-event-categories',
'node.console'
]
});

proc.once('exit', common.mustCall(async () => {
const file = path.join(tmpdir.path, 'node_trace.1.log');

assert(fs.existsSync(file));
const data = await fs.promises.readFile(file, { encoding: 'utf8' });
JSON.parse(data).traceEvents
.filter((trace) => trace.cat !== '__metadata')
.forEach((trace) => {
assert.strictEqual(trace.pid, proc.pid);
assert(names.includes(trace.name));
if (trace.name === 'count::bar')
assert.strictEqual(trace.args.data, expectedCounts.shift());
else if (trace.name === 'time::foo')
assert.strictEqual(trace.ph, expectedTimeTypes.shift());
});
assert.strictEqual(expectedCounts.length, 0);
assert.strictEqual(expectedTimeTypes.length, 0);
}));
}

0 comments on commit b164a2e

Please sign in to comment.