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: nodejs#23703
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
  • Loading branch information
jasnell committed Oct 18, 2018
1 parent bf7ed80 commit 9c82a1e
Show file tree
Hide file tree
Showing 3 changed files with 76 additions and 1 deletion.
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.environment` - Enables capture of Node.js Environment milestones.
* `node.fs.sync` - Enables capture of trace data for file system sync methods.
* `node.perf` - Enables capture of [Performance API] measurements.
Expand Down
13 changes: 12 additions & 1 deletion 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 @@ -232,13 +239,15 @@ Console.prototype.time = function time(label = 'default') {
process.emitWarning(`Label '${label}' already exists for console.time()`);
return;
}
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 @@ -248,6 +257,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 @@ -308,6 +318,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 @@ -318,7 +329,7 @@ Console.prototype.countReset = function countReset(label = 'default') {
process.emitWarning(`Count for '${label}' does not exist`);
return;
}

trace(kTraceCount, kTraceConsoleCategory, `count::${label}`, 0, 0);
counts.delete(`${label}`);
};

Expand Down
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 9c82a1e

Please sign in to comment.