lib: support dynamic trace events on debugWithTimer

PR-URL: nodejs#53913
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Rafael Gonzaga <[email protected]>

Author: H4ad

lib/internal/util/debuglog.js

@@ -20,7 +20,7 @@ const {
   CHAR_LOWERCASE_N: kTraceInstant,
 } = require('internal/constants');
 const { inspect, format, formatWithOptions } = require('internal/util/inspect');
-const { isTraceCategoryEnabled, trace } = internalBinding('trace_events');
+const { getCategoryEnabledBuffer, trace } = internalBinding('trace_events');
 
 // `debugImpls` and `testEnabled` are deliberately not initialized so any call
 // to `debuglog()` before `initializeDebugEnv()` is called will throw.
@@ -372,18 +372,34 @@ function debugWithTimer(set, cb) {
       );
   }
 
-  const kTraceCategory = `node,node.${StringPrototypeToLowerCase(set)}`;
+  const traceCategory = `node,node.${StringPrototypeToLowerCase(set)}`;
+  let traceCategoryBuffer;
   let debugLogCategoryEnabled = false;
-  let traceCategoryEnabled = false;
   let timerFlags = kNone;
 
+  const skipAll = kSkipLog | kSkipTrace;
+
+  function ensureTimerFlagsAreUpdated() {
+    timerFlags &= ~kSkipTrace;
+
+    if (traceCategoryBuffer[0] === 0) {
+      timerFlags |= kSkipTrace;
+    }
+  }
+
   /**
    * @type {TimerStart}
    */
   function internalStartTimer(logLabel, traceLabel) {
+    ensureTimerFlagsAreUpdated();
+
+    if (timerFlags === skipAll) {
+      return;
+    }
+
     time(
       tracesStores[set],
-      kTraceCategory,
+      traceCategory,
       'debuglog.time',
       timerFlags,
       logLabel,
@@ -395,9 +411,15 @@ function debugWithTimer(set, cb) {
    * @type {TimerEnd}
    */
   function internalEndTimer(logLabel, traceLabel) {
+    ensureTimerFlagsAreUpdated();
+
+    if (timerFlags === skipAll) {
+      return;
+    }
+
     timeEnd(
       tracesStores[set],
-      kTraceCategory,
+      traceCategory,
       'debuglog.timeEnd',
       timerFlags,
       logImpl,
@@ -410,9 +432,15 @@ function debugWithTimer(set, cb) {
    * @type {TimerLog}
    */
   function internalLogTimer(logLabel, traceLabel, args) {
+    ensureTimerFlagsAreUpdated();
+
+    if (timerFlags === skipAll) {
+      return;
+    }
+
     timeLog(
       tracesStores[set],
-      kTraceCategory,
+      traceCategory,
       'debuglog.timeLog',
       timerFlags,
       logImpl,
@@ -428,21 +456,19 @@ function debugWithTimer(set, cb) {
     }
     emitWarningIfNeeded(set);
     debugLogCategoryEnabled = testEnabled(set);
-    traceCategoryEnabled = isTraceCategoryEnabled(kTraceCategory);
+    traceCategoryBuffer = getCategoryEnabledBuffer(traceCategory);
+
+    timerFlags = kNone;
 
     if (!debugLogCategoryEnabled) {
       timerFlags |= kSkipLog;
     }
 
-    if (!traceCategoryEnabled) {
+    if (traceCategoryBuffer[0] === 0) {
       timerFlags |= kSkipTrace;
     }
 
-    // TODO(H4ad): support traceCategory being enabled dynamically
-    if (debugLogCategoryEnabled || traceCategoryEnabled)
-      cb(internalStartTimer, internalEndTimer, internalLogTimer);
-    else
-      cb(noop, noop, noop);
+    cb(internalStartTimer, internalEndTimer, internalLogTimer);
   }
 
   /**
@@ -451,7 +477,7 @@ function debugWithTimer(set, cb) {
   const startTimer = (logLabel, traceLabel) => {
     init();
 
-    if (debugLogCategoryEnabled || traceCategoryEnabled)
+    if (timerFlags !== skipAll)
       internalStartTimer(logLabel, traceLabel);
   };
 
@@ -461,7 +487,7 @@ function debugWithTimer(set, cb) {
   const endTimer = (logLabel, traceLabel) => {
     init();
 
-    if (debugLogCategoryEnabled || traceCategoryEnabled)
+    if (timerFlags !== skipAll)
       internalEndTimer(logLabel, traceLabel);
   };
 
@@ -471,7 +497,7 @@ function debugWithTimer(set, cb) {
   const logTimer = (logLabel, traceLabel, args) => {
     init();
 
-    if (debugLogCategoryEnabled || traceCategoryEnabled)
+    if (timerFlags !== skipAll)
       internalLogTimer(logLabel, traceLabel, args);
   };
 

test/parallel/test-module-print-timing.mjs

@@ -16,7 +16,7 @@ it('should print the timing information for cjs', () => {
     },
   }, {
     stdout: '',
-    stderr: (result) => result.includes('MODULE_TIMER'),
+    stderr: /MODULE_TIMER/g,
   });
 
   const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
@@ -74,7 +74,7 @@ it('should write tracing & print logs for cjs', async () => {
     },
   }, {
     stdout: '',
-    stderr: (result) => result.includes('MODULE_TIMER'),
+    stderr: /MODULE_TIMER/g,
   });
 
   const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
@@ -89,7 +89,67 @@ it('should write tracing & print logs for cjs', async () => {
   const outputFileJson = JSON.parse(outputFileContent).traceEvents;
   const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')");
 
+  assert.ok(urlTraces.length > 0, 'Not found url traces');
+
   for (const trace of urlTraces) {
     assert.strictEqual(trace.ph, expectedMimeTypes.shift());
   }
 });
+
+it('should support enable tracing dynamically', async () => {
+  try {
+    spawnSyncAndAssert(process.execPath, [
+      '--eval',
+      'require("trace_events")',
+    ], {
+      stdout: '',
+      stderr: '',
+    });
+  } catch {
+    // Skip this test if the trace_events module is not available
+    return;
+  }
+
+
+  const outputFile = tmpdir.resolve('output-dynamic-trace.log');
+  const jsScript = `
+  const traceEvents = require("trace_events");
+  const tracing = traceEvents.createTracing({ categories: ["node.module_timer"] });
+
+  tracing.enable();
+  require("http");
+  tracing.disable();
+
+  require("vm");
+  `;
+
+  spawnSyncAndAssert(process.execPath, [
+    '--trace-event-file-pattern',
+    outputFile,
+    '--eval',
+    jsScript,
+  ], {
+    cwd: tmpdir.path,
+    env: {
+      ...process.env,
+    },
+  }, {
+    stdout: '',
+    stderr: '',
+  });
+
+  const expectedMimeTypes = ['b', 'e'];
+  const outputFileContent = await readFile(outputFile, 'utf-8');
+
+  const outputFileJson = JSON.parse(outputFileContent).traceEvents;
+  const httpTraces = outputFileJson.filter((trace) => trace.name === "require('http')");
+
+  assert.ok(httpTraces.length > 0, 'Not found http traces');
+
+  for (const trace of httpTraces) {
+    assert.strictEqual(trace.ph, expectedMimeTypes.shift());
+  }
+
+  const vmTraces = outputFileJson.filter((trace) => trace.name === "require('vm')");
+  assert.strictEqual(vmTraces.length, 0);
+});