diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index e4a283d9faa767..87d19dcc843170 100644 --- a/lib/internal/util/debuglog.js +++ b/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); }; diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 0cb7189d3114af..124ac5e2763e8c 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/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); +});