lib: support dynamic trace events on debugWithTimer

PR-URL: #53913
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Rafael Gonzaga <rafael.nunu@hotmail.com>

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) {
 );
 }
 
-constkTraceCategory=`node,node.${StringPrototypeToLowerCase(set)}`;
+consttraceCategory=`node,node.${StringPrototypeToLowerCase(set)}`;
+lettraceCategoryBuffer;
 letdebugLogCategoryEnabled=false;
-lettraceCategoryEnabled=false;
 lettimerFlags=kNone;
 
+constskipAll=kSkipLog|kSkipTrace;
+
+functionensureTimerFlagsAreUpdated(){
+timerFlags&=~kSkipTrace;
+
+if(traceCategoryBuffer[0]===0){
+timerFlags|=kSkipTrace;
+}
+}
+
 /**
  * @type {TimerStart}
  */
 functioninternalStartTimer(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}
  */
 functioninternalEndTimer(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}
  */
 functioninternalLogTimer(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) {
 conststartTimer=(logLabel,traceLabel)=>{
 init();
 
-if(debugLogCategoryEnabled||traceCategoryEnabled)
+if(timerFlags!==skipAll)
 internalStartTimer(logLabel,traceLabel);
 };
 
@@ -461,7 +487,7 @@ function debugWithTimer(set, cb) {
 constendTimer=(logLabel,traceLabel)=>{
 init();
 
-if(debugLogCategoryEnabled||traceCategoryEnabled)
+if(timerFlags!==skipAll)
 internalEndTimer(logLabel,traceLabel);
 };
 
@@ -471,7 +497,7 @@ function debugWithTimer(set, cb) {
 constlogTimer=(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,
 });
 
 constfirstLine=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,
 });
 
 constfirstLine=result.stderr.split('\n').find((line)=>line.includes('[url]'));
@@ -89,7 +89,67 @@ it('should write tracing & print logs for cjs', async () => {
 constoutputFileJson=JSON.parse(outputFileContent).traceEvents;
 consturlTraces=outputFileJson.filter((trace)=>trace.name==="require('url')");
 
+assert.ok(urlTraces.length>0,'Not found url traces');
+
 for(consttraceofurlTraces){
 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;
+}
+
+
+constoutputFile=tmpdir.resolve('output-dynamic-trace.log');
+constjsScript=`
+ 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: '',
+});
+
+constexpectedMimeTypes=['b','e'];
+constoutputFileContent=awaitreadFile(outputFile,'utf-8');
+
+constoutputFileJson=JSON.parse(outputFileContent).traceEvents;
+consthttpTraces=outputFileJson.filter((trace)=>trace.name==="require('http')");
+
+assert.ok(httpTraces.length>0,'Not found http traces');
+
+for(consttraceofhttpTraces){
+assert.strictEqual(trace.ph,expectedMimeTypes.shift());
+}
+
+constvmTraces=outputFileJson.filter((trace)=>trace.name==="require('vm')");
+assert.strictEqual(vmTraces.length,0);
+});