From cb9a2cead330169e2456d5d9d02c5fbf8b79f04b Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 16 Oct 2018 13:57:24 -0700 Subject: [PATCH] console: add trace-events for time and count 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. --- doc/api/tracing.md | 2 + lib/console.js | 13 ++++- test/parallel/test-trace-events-console.js | 62 ++++++++++++++++++++++ 3 files changed, 76 insertions(+), 1 deletion(-) create mode 100644 test/parallel/test-trace-events-console.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index d58079360a0056..04db3f12f42e2e 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.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. diff --git a/lib/console.js b/lib/console.js index c254a3889b7856..96bd1855859809 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, @@ -232,6 +239,7 @@ 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()); }; @@ -239,6 +247,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); } @@ -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 @@ -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}`); }; @@ -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}`); }; 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); + })); +}