add trace label to better visualization

Author: H4ad

lib/internal/console/constructor.js

@@ -393,21 +393,21 @@ const consoleMethods = {
   },
 
   time(label = 'default') {
-    time(this._times, kTraceConsoleCategory, 'console.time()', label);
+    time(this._times, kTraceConsoleCategory, 'console.time()', label, `time::${label}`);
   },
 
   timeEnd(label = 'default') {
     if (this[kInternalTimeLogImpl] === undefined)
       this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
 
-    timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label);
+    timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label, `time::${label}`);
   },
 
   timeLog(label = 'default', ...data) {
     if (this[kInternalTimeLogImpl] === undefined)
       this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
 
-    timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, data);
+    timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, `time::${label}`, data);
   },
 
   trace: function trace(...args) {

lib/internal/modules/cjs/loader.js

@@ -977,9 +977,10 @@ function getExportsForCircularRequire(module) {
  * @param {boolean} isMain Whether the module is the main entry point
  */
 Module._load = function(request, parent, isMain) {
-  const label = `[${parent?.id || ''}] [${request}]`;
+  const logLabel = `[${parent?.id || ''}] [${request}]`;
+  const traceLabel = `require('${request}')`;
 
-  startTimer(label);
+  startTimer(logLabel, traceLabel);
 
   let relResolveCacheIdentifier;
   if (parent) {
@@ -997,12 +998,12 @@ Module._load = function(request, parent, isMain) {
         if (!cachedModule.loaded) {
           const result = getExportsForCircularRequire(cachedModule);
 
-          endTimer(label);
+          endTimer(logLabel, traceLabel);
 
           return result;
         }
 
-        endTimer(label);
+        endTimer(logLabel, traceLabel);
         return cachedModule.exports;
       }
       delete relativeResolveCache[relResolveCacheIdentifier];
@@ -1019,7 +1020,7 @@ Module._load = function(request, parent, isMain) {
 
     const module = loadBuiltinModule(id, request);
 
-    endTimer(label);
+    endTimer(logLabel, traceLabel);
     return module.exports;
   }
 
@@ -1032,21 +1033,21 @@ Module._load = function(request, parent, isMain) {
       if (!parseCachedModule || parseCachedModule.loaded) {
         const result = getExportsForCircularRequire(cachedModule);
 
-        endTimer(label);
+        endTimer(logLabel, traceLabel);
 
         return result;
       }
       parseCachedModule.loaded = true;
     } else {
-      endTimer(label);
+      endTimer(logLabel, traceLabel);
       return cachedModule.exports;
     }
   }
 
   if (BuiltinModule.canBeRequiredWithoutScheme(filename)) {
     const mod = loadBuiltinModule(filename, request);
 
-    endTimer(label);
+    endTimer(logLabel, traceLabel);
 
     return mod.exports;
   }
@@ -1095,7 +1096,7 @@ Module._load = function(request, parent, isMain) {
     }
   }
 
-  endTimer(label);
+  endTimer(logLabel, traceLabel);
 
   return module.exports;
 };

lib/internal/util/debuglog.js

@@ -148,15 +148,15 @@ function buildCategory(set) {
 let tracesStores;
 
 /**
- * @typedef {(label: string) => void} TimerStart
+ * @typedef {(logLabel: string, traceLabel?: string) => void} TimerStart
  */
 
 /**
- * @typedef {(label: string) => void} TimerEnd
+ * @typedef {(label: string, traceLabel?: string) => void} TimerEnd
  */
 
 /**
- * @typedef {(label: string, args?: any[]) => void} TimerLog
+ * @typedef {(label: string, traceLabel?: string, args?: any[]) => void} TimerLog
  */
 
 /**
@@ -205,34 +205,34 @@ function debugWithTimer(set, cb) {
   /**
    * @type {TimerStart}
    */
-  function internalStartTimer(label) {
+  function internalStartTimer(logLabel, traceLabel) {
     if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) {
       return;
     }
 
-    time(tracesStores[set], kTraceCategory, 'debuglog.time', label);
+    time(tracesStores[set], kTraceCategory, 'debuglog.time', logLabel, traceLabel);
   }
 
   /**
    * @type {TimerEnd}
    */
-  function internalEndTimer(label) {
+  function internalEndTimer(logLabel, traceLabel) {
     if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) {
       return;
     }
 
-    timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, label);
+    timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel);
   }
 
   /**
    * @type {TimerLog}
    */
-  function internalLogTimer(label, args) {
+  function internalLogTimer(logLabel, traceLabel, args) {
     if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) {
       return;
     }
 
-    timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, label, args);
+    timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args);
   }
 
   function init() {
@@ -247,37 +247,37 @@ function debugWithTimer(set, cb) {
   /**
    * @type {TimerStart}
    */
-  const startTimer = (label) => {
+  const startTimer = (logLabel, traceLabel) => {
     init();
 
     if (cb)
       cb(internalStartTimer, internalEndTimer, internalLogTimer);
 
-    return internalStartTimer(label);
+    return internalStartTimer(logLabel, traceLabel);
   };
 
   /**
    * @type {TimerEnd}
    */
-  const endTimer = (label) => {
+  const endTimer = (logLabel, traceLabel) => {
     init();
 
     if (cb)
       cb(internalStartTimer, internalEndTimer, internalLogTimer);
 
-    return internalEndTimer(label);
+    return internalEndTimer(logLabel, traceLabel);
   };
 
   /**
    * @type {TimerLog}
    */
-  const logTimer = (label, args) => {
+  const logTimer = (logLabel, traceLabel, args) => {
     init();
 
     if (cb)
       cb(internalStartTimer, internalEndTimer, internalLogTimer);
 
-    return internalLogTimer(label, args);
+    return internalLogTimer(logLabel, traceLabel, args);
   };
 
   return {

lib/internal/util/trace_timer.js

@@ -95,38 +95,52 @@ function timeLogImpl(timesStore, implementation, logImp, label, args) {
  * @param {SafeMap} timesStore
  * @param {string} traceCategory
  * @param {string} implementation
- * @param {string} label
+ * @param {string} logLabel
  * @returns {void}
  */
-function time(timesStore, traceCategory, implementation, label = 'default') {
+function time(timesStore, traceCategory, implementation, logLabel = 'default', traceLabel = undefined) {
   // Coerces everything other than Symbol to a string
-  label = `${label}`;
-  if (timesStore.has(label)) {
-    process.emitWarning(`Label '${label}' already exists for ${implementation}`);
+  logLabel = `${logLabel}`;
+
+  if (traceLabel !== undefined) {
+    traceLabel = `${traceLabel}`;
+  } else {
+    traceLabel = logLabel;
+  }
+
+  if (timesStore.has(logLabel)) {
+    process.emitWarning(`Label '${logLabel}' already exists for ${implementation}`);
     return;
   }
 
-  trace(kTraceBegin, traceCategory, `time::${label}`, 0);
-  timesStore.set(label, process.hrtime());
+  trace(kTraceBegin, traceCategory, traceLabel, 0);
+  timesStore.set(logLabel, process.hrtime());
 }
 
 /**
  * @param {SafeMap} timesStore
  * @param {string} traceCategory
  * @param {string} implementation
  * @param {LogImpl} logImpl
- * @param {string} label
+ * @param {string} logLabel
+ * @param {string} traceLabel
  * @returns {void}
  */
-function timeEnd(timesStore, traceCategory, implementation, logImpl, label = 'default') {
+function timeEnd(timesStore, traceCategory, implementation, logImpl, logLabel = 'default', traceLabel = undefined) {
   // Coerces everything other than Symbol to a string
-  label = `${label}`;
+  logLabel = `${logLabel}`;
+
+  if (traceLabel !== undefined) {
+    traceLabel = `${traceLabel}`;
+  } else {
+    traceLabel = logLabel;
+  }
 
-  const found = timeLogImpl(timesStore, implementation, logImpl, label);
-  trace(kTraceEnd, traceCategory, `time::${label}`, 0);
+  const found = timeLogImpl(timesStore, implementation, logImpl, logLabel);
+  trace(kTraceEnd, traceCategory, traceLabel, 0);
 
   if (found) {
-    timesStore.delete(label);
+    timesStore.delete(logLabel);
   }
 }
 
@@ -135,16 +149,24 @@ function timeEnd(timesStore, traceCategory, implementation, logImpl, label = 'de
  * @param {string} traceCategory
  * @param {string} implementation
  * @param {LogImpl} logImpl
- * @param {string} label
+ * @param {string} logLabel
+ * @param {string} traceLabel
  * @param {any[]} args
  * @returns {void}
  */
-function timeLog(timesStore, traceCategory, implementation, logImpl, label = 'default', args) {
+function timeLog(timesStore, traceCategory, implementation, logImpl, logLabel = 'default', traceLabel = undefined, args) {
   // Coerces everything other than Symbol to a string
-  label = `${label}`;
-  timeLogImpl(timesStore, implementation, logImpl, label, args);
+  logLabel = `${logLabel}`;
+
+  if (traceLabel !== undefined) {
+    traceLabel = `${traceLabel}`;
+  } else {
+    traceLabel = logLabel;
+  }
+
+  timeLogImpl(timesStore, implementation, logImpl, logLabel, args);
 
-  trace(kTraceInstant, traceCategory, `time::${label}`, 0);
+  trace(kTraceInstant, traceCategory, traceLabel, 0);
 }
 
 module.exports = {