diff --git a/doc/api/tracing.md b/doc/api/tracing.md index fb855084022a6c..69f5b53891ae41 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -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 diff --git a/lib/console.js b/lib/console.js index ffa6ec09c80c3c..f4aab10a52be94 100644 --- a/lib/console.js +++ b/lib/console.js @@ -21,6 +21,7 @@ 'use strict'; +const { trace } = internalBinding('trace_events'); const { isStackOverflowError, codes: { @@ -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, @@ -230,6 +237,7 @@ 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()); }; @@ -237,6 +245,7 @@ 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); } @@ -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 @@ -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}`); }; @@ -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}`); }; diff --git a/test/parallel/test-bootstrap-modules.js b/test/parallel/test-bootstrap-modules.js index e2c7836a362abc..f3705b7915377c 100644 --- a/test/parallel/test-bootstrap-modules.js +++ b/test/parallel/test-bootstrap-modules.js @@ -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}`); diff --git a/test/parallel/test-trace-events-console.js b/test/parallel/test-trace-events-console.js new file mode 100644 index 00000000000000..a4860b5da008b4 --- /dev/null +++ b/test/parallel/test-trace-events-console.js @@ -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); + })); +}