GV

GeezerVison

The World Wide Web, restored to 800 pixels of glory.

Home|About|Gaming cabinet|Archives|How it works|Starter sites

On this site

  • Sign in
  • ActionsCI/CD and automation
  • CodespacesCloud development environments
  • All Features
  • Documentation
  • Training
  • Certifications
  • Build with Copilot
  • Customize Copilot
  • Integrations
  • Trending repos
  • GitHub Sponsors
  • Developer articles
  • Enterprises

This view

  • Original page
  • New address

GeezerVison is showing github.com — lib: support dynamic trace events on debugWithTimer · nodejs/node@744df0b

File tree

Expand file treeCollapse file tree
Open diff view settings
Filter options
  • lib/internal/util
    • debuglog.js
  • test/parallel
    • test-module-print-timing.mjs
Expand file treeCollapse file tree
Open diff view settings
Collapse file

‎lib/internal/util/debuglog.js‎

Copy file name to clipboardExpand all lines: lib/internal/util/debuglog.js
+42-16Lines changed: 42 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ const {
2020
CHAR_LOWERCASE_N: kTraceInstant,
2121
} = require('internal/constants');
2222
const { inspect, format, formatWithOptions } = require('internal/util/inspect');
23-
const { isTraceCategoryEnabled, trace } = internalBinding('trace_events');
23+
const { getCategoryEnabledBuffer, trace } = internalBinding('trace_events');
2424

2525
// `debugImpls` and `testEnabled` are deliberately not initialized so any call
2626
// to `debuglog()` before `initializeDebugEnv()` is called will throw.
@@ -372,18 +372,34 @@ function debugWithTimer(set, cb) {
372372
);
373373
}
374374

375-
const kTraceCategory = `node,node.${StringPrototypeToLowerCase(set)}`;
375+
const traceCategory = `node,node.${StringPrototypeToLowerCase(set)}`;
376+
let traceCategoryBuffer;
376377
let debugLogCategoryEnabled = false;
377-
let traceCategoryEnabled = false;
378378
let timerFlags = kNone;
379379

380+
const skipAll = kSkipLog | kSkipTrace;
381+
382+
function ensureTimerFlagsAreUpdated() {
383+
timerFlags &= ~kSkipTrace;
384+
385+
if (traceCategoryBuffer[0] === 0) {
386+
timerFlags |= kSkipTrace;
387+
}
388+
}
389+
380390
/**
381391
* @type {TimerStart}
382392
*/
383393
function internalStartTimer(logLabel, traceLabel) {
394+
ensureTimerFlagsAreUpdated();
395+
396+
if (timerFlags === skipAll) {
397+
return;
398+
}
399+
384400
time(
385401
tracesStores[set],
386-
kTraceCategory,
402+
traceCategory,
387403
'debuglog.time',
388404
timerFlags,
389405
logLabel,
@@ -395,9 +411,15 @@ function debugWithTimer(set, cb) {
395411
* @type {TimerEnd}
396412
*/
397413
function internalEndTimer(logLabel, traceLabel) {
414+
ensureTimerFlagsAreUpdated();
415+
416+
if (timerFlags === skipAll) {
417+
return;
418+
}
419+
398420
timeEnd(
399421
tracesStores[set],
400-
kTraceCategory,
422+
traceCategory,
401423
'debuglog.timeEnd',
402424
timerFlags,
403425
logImpl,
@@ -410,9 +432,15 @@ function debugWithTimer(set, cb) {
410432
* @type {TimerLog}
411433
*/
412434
function internalLogTimer(logLabel, traceLabel, args) {
435+
ensureTimerFlagsAreUpdated();
436+
437+
if (timerFlags === skipAll) {
438+
return;
439+
}
440+
413441
timeLog(
414442
tracesStores[set],
415-
kTraceCategory,
443+
traceCategory,
416444
'debuglog.timeLog',
417445
timerFlags,
418446
logImpl,
@@ -428,21 +456,19 @@ function debugWithTimer(set, cb) {
428456
}
429457
emitWarningIfNeeded(set);
430458
debugLogCategoryEnabled = testEnabled(set);
431-
traceCategoryEnabled = isTraceCategoryEnabled(kTraceCategory);
459+
traceCategoryBuffer = getCategoryEnabledBuffer(traceCategory);
460+
461+
timerFlags = kNone;
432462

433463
if (!debugLogCategoryEnabled) {
434464
timerFlags |= kSkipLog;
435465
}
436466

437-
if (!traceCategoryEnabled) {
467+
if (traceCategoryBuffer[0] === 0) {
438468
timerFlags |= kSkipTrace;
439469
}
440470

441-
// TODO(H4ad): support traceCategory being enabled dynamically
442-
if (debugLogCategoryEnabled || traceCategoryEnabled)
443-
cb(internalStartTimer, internalEndTimer, internalLogTimer);
444-
else
445-
cb(noop, noop, noop);
471+
cb(internalStartTimer, internalEndTimer, internalLogTimer);
446472
}
447473

448474
/**
@@ -451,7 +477,7 @@ function debugWithTimer(set, cb) {
451477
const startTimer = (logLabel, traceLabel) => {
452478
init();
453479

454-
if (debugLogCategoryEnabled || traceCategoryEnabled)
480+
if (timerFlags !== skipAll)
455481
internalStartTimer(logLabel, traceLabel);
456482
};
457483

@@ -461,7 +487,7 @@ function debugWithTimer(set, cb) {
461487
const endTimer = (logLabel, traceLabel) => {
462488
init();
463489

464-
if (debugLogCategoryEnabled || traceCategoryEnabled)
490+
if (timerFlags !== skipAll)
465491
internalEndTimer(logLabel, traceLabel);
466492
};
467493

@@ -471,7 +497,7 @@ function debugWithTimer(set, cb) {
471497
const logTimer = (logLabel, traceLabel, args) => {
472498
init();
473499

474-
if (debugLogCategoryEnabled || traceCategoryEnabled)
500+
if (timerFlags !== skipAll)
475501
internalLogTimer(logLabel, traceLabel, args);
476502
};
477503

Collapse file

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

Copy file name to clipboardExpand all lines: test/parallel/test-module-print-timing.mjs
+62-2Lines changed: 62 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ it('should print the timing information for cjs', () => {
1616
},
1717
}, {
1818
stdout: '',
19-
stderr: (result) => result.includes('MODULE_TIMER'),
19+
stderr: /MODULE_TIMER/g,
2020
});
2121

2222
const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
@@ -74,7 +74,7 @@ it('should write tracing & print logs for cjs', async () => {
7474
},
7575
}, {
7676
stdout: '',
77-
stderr: (result) => result.includes('MODULE_TIMER'),
77+
stderr: /MODULE_TIMER/g,
7878
});
7979

8080
const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
@@ -89,7 +89,67 @@ it('should write tracing & print logs for cjs', async () => {
8989
const outputFileJson = JSON.parse(outputFileContent).traceEvents;
9090
const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')");
9191

92+
assert.ok(urlTraces.length > 0, 'Not found url traces');
93+
9294
for (const trace of urlTraces) {
9395
assert.strictEqual(trace.ph, expectedMimeTypes.shift());
9496
}
9597
});
98+
99+
it('should support enable tracing dynamically', async () => {
100+
try {
101+
spawnSyncAndAssert(process.execPath, [
102+
'--eval',
103+
'require("trace_events")',
104+
], {
105+
stdout: '',
106+
stderr: '',
107+
});
108+
} catch {
109+
// Skip this test if the trace_events module is not available
110+
return;
111+
}
112+
113+
114+
const outputFile = tmpdir.resolve('output-dynamic-trace.log');
115+
const jsScript = `
116+
const traceEvents = require("trace_events");
117+
const tracing = traceEvents.createTracing({ categories: ["node.module_timer"] });
118+
119+
tracing.enable();
120+
require("http");
121+
tracing.disable();
122+
123+
require("vm");
124+
`;
125+
126+
spawnSyncAndAssert(process.execPath, [
127+
'--trace-event-file-pattern',
128+
outputFile,
129+
'--eval',
130+
jsScript,
131+
], {
132+
cwd: tmpdir.path,
133+
env: {
134+
...process.env,
135+
},
136+
}, {
137+
stdout: '',
138+
stderr: '',
139+
});
140+
141+
const expectedMimeTypes = ['b', 'e'];
142+
const outputFileContent = await readFile(outputFile, 'utf-8');
143+
144+
const outputFileJson = JSON.parse(outputFileContent).traceEvents;
145+
const httpTraces = outputFileJson.filter((trace) => trace.name === "require('http')");
146+
147+
assert.ok(httpTraces.length > 0, 'Not found http traces');
148+
149+
for (const trace of httpTraces) {
150+
assert.strictEqual(trace.ph, expectedMimeTypes.shift());
151+
}
152+
153+
const vmTraces = outputFileJson.filter((trace) => trace.name === "require('vm')");
154+
assert.strictEqual(vmTraces.length, 0);
155+
});

0 commit comments

Comments
0 (0)
You are visitor 01402503 — GeezerVison does not store the pages you look up.
Best viewed with Netscape Navigator 4.7 or Internet Explorer 6 at 800×600. No cookies required.