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.

PR-URL: #23703
Backport-PR-URL: #28840
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>

Author: jasnell

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

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,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);
   }
@@ -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}`);
 };
 

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}`);

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);
+  }));
+}