From bcc756f89fcc77d379a941ff4044ca8576170078 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 17 Jul 2024 22:10:16 -0300 Subject: [PATCH 1/4] lib: support dynamic trace events on debugWithTimer --- lib/internal/util/debuglog.js | 53 ++++++++++++++++------ test/parallel/test-module-print-timing.mjs | 50 +++++++++++++++++++- 2 files changed, 86 insertions(+), 17 deletions(-) diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index e4a283d9faa767..07610e367a20cf 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,35 @@ 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 +412,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 +433,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 +457,15 @@ function debugWithTimer(set, cb) { } emitWarningIfNeeded(set); debugLogCategoryEnabled = testEnabled(set); - traceCategoryEnabled = isTraceCategoryEnabled(kTraceCategory); + traceCategoryBuffer = getCategoryEnabledBuffer(traceCategory); + + timerFlags = kNone; if (!debugLogCategoryEnabled) { timerFlags |= kSkipLog; } - if (!traceCategoryEnabled) { - 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); } /** diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 0cb7189d3114af..57ecf884f2f764 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,53 @@ 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 () => { + 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); +}); From a502ec13252b429d619a42586c3d0327ce32b7eb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 17 Jul 2024 22:21:38 -0300 Subject: [PATCH 2/4] minor fix on lint --- lib/internal/util/debuglog.js | 11 +++++++---- test/parallel/test-module-print-timing.mjs | 2 +- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 07610e367a20cf..87d19dcc843170 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -375,7 +375,6 @@ function debugWithTimer(set, cb) { const traceCategory = `node,node.${StringPrototypeToLowerCase(set)}`; let traceCategoryBuffer; let debugLogCategoryEnabled = false; - let traceCategoryEnabled = false; let timerFlags = kNone; const skipAll = kSkipLog | kSkipTrace; @@ -465,6 +464,10 @@ function debugWithTimer(set, cb) { timerFlags |= kSkipLog; } + if (traceCategoryBuffer[0] === 0) { + timerFlags |= kSkipTrace; + } + cb(internalStartTimer, internalEndTimer, internalLogTimer); } @@ -474,7 +477,7 @@ function debugWithTimer(set, cb) { const startTimer = (logLabel, traceLabel) => { init(); - if (debugLogCategoryEnabled || traceCategoryEnabled) + if (timerFlags !== skipAll) internalStartTimer(logLabel, traceLabel); }; @@ -484,7 +487,7 @@ function debugWithTimer(set, cb) { const endTimer = (logLabel, traceLabel) => { init(); - if (debugLogCategoryEnabled || traceCategoryEnabled) + if (timerFlags !== skipAll) internalEndTimer(logLabel, traceLabel); }; @@ -494,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 57ecf884f2f764..6ea44fe99a8a49 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -107,7 +107,7 @@ it('should support enable tracing dynamically', async () => { tracing.disable(); require("vm"); - ` + `; spawnSyncAndAssert(process.execPath, [ '--trace-event-file-pattern', From 7212c8f50c4f6114a27f3498982dbbb6dedabf47 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 27 Jul 2024 14:14:41 -0300 Subject: [PATCH 3/4] fix issue with trace events not found --- test/parallel/test-module-print-timing.mjs | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 6ea44fe99a8a49..05418b15cf5dec 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -97,6 +97,20 @@ it('should write tracing & print logs for cjs', async () => { }); it('should support enable tracing dynamically', async () => { + try { + spawnSyncAndAssert(process.execPath, [ + '--eval', + 'require("trace_events")', + ], { + stdout: '', + stderr: '', + }); + } catch (err) { + // 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"); From 18581bc98542c7cddfa698224a2586b62a9cb3e4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 27 Jul 2024 14:23:35 -0300 Subject: [PATCH 4/4] fix lint on test --- test/parallel/test-module-print-timing.mjs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 05418b15cf5dec..124ac5e2763e8c 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -105,7 +105,7 @@ it('should support enable tracing dynamically', async () => { stdout: '', stderr: '', }); - } catch (err) { + } catch { // Skip this test if the trace_events module is not available return; }