try support both node_debug and trace by introducing a new module

Author: H4ad

lib/internal/console/constructor.js

@@ -12,9 +12,6 @@ const {
   Boolean,
   ErrorCaptureStackTrace,
   FunctionPrototypeBind,
-  MathFloor,
-  Number,
-  NumberPrototypeToFixed,
   ObjectDefineProperties,
   ObjectDefineProperty,
   ObjectKeys,
@@ -29,10 +26,8 @@ const {
   SafeWeakMap,
   SafeSet,
   StringPrototypeIncludes,
-  StringPrototypePadStart,
   StringPrototypeRepeat,
   StringPrototypeSlice,
-  StringPrototypeSplit,
   Symbol,
   SymbolHasInstance,
   SymbolToStringTag,
@@ -62,18 +57,13 @@ const {
   isTypedArray, isSet, isMap, isSetIterator, isMapIterator,
 } = require('internal/util/types');
 const {
-  CHAR_LOWERCASE_B: kTraceBegin,
-  CHAR_LOWERCASE_E: kTraceEnd,
-  CHAR_LOWERCASE_N: kTraceInstant,
   CHAR_UPPERCASE_C: kTraceCount,
 } = require('internal/constants');
 const kCounts = Symbol('counts');
+const { time, timeEnd, timeLog } = require('internal/util/trace_timer');
 
 const kTraceConsoleCategory = 'node,node.console';
 
-const kSecond = 1000;
-const kMinute = 60 * kSecond;
-const kHour = 60 * kMinute;
 const kMaxGroupIndentation = 1000;
 
 // Lazy loaded for startup performance.
@@ -99,6 +89,7 @@ const kBindStreamsEager = Symbol('kBindStreamsEager');
 const kBindStreamsLazy = Symbol('kBindStreamsLazy');
 const kUseStdout = Symbol('kUseStdout');
 const kUseStderr = Symbol('kUseStderr');
+const kInternalTimeLogImpl = Symbol('kInternalTimeLogImpl');
 
 const optionsMap = new SafeWeakMap();
 function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
@@ -145,7 +136,7 @@ function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
     validateObject(inspectOptions, 'options.inspectOptions');
 
     if (inspectOptions.colors !== undefined &&
-        options.colorMode !== undefined) {
+      options.colorMode !== undefined) {
       throw new ERR_INCOMPATIBLE_OPTION_PAIR(
         'options.inspectOptions.color', 'colorMode');
     }
@@ -374,6 +365,14 @@ function createWriteErrorHandler(instance, streamSymbol) {
   };
 }
 
+function timeLogImpl(label, formatted, args) {
+  if (args === undefined) {
+    this.log('%s: %s', label, formatted);
+  } else {
+    this.log('%s: %s', label, formatted, ...new SafeArrayIterator(args));
+  }
+}
+
 const consoleMethods = {
   log(...args) {
     this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args));
@@ -394,31 +393,21 @@ const consoleMethods = {
   },
 
   time(label = 'default') {
-    // Coerces everything other than Symbol to a string
-    label = `${label}`;
-    if (this._times.has(label)) {
-      process.emitWarning(`Label '${label}' already exists for console.time()`);
-      return;
-    }
-    trace(kTraceBegin, kTraceConsoleCategory, `time::${label}`, 0);
-    this._times.set(label, process.hrtime());
+    time(this._times, kTraceConsoleCategory, 'console.time()', label);
   },
 
   timeEnd(label = 'default') {
-    // Coerces everything other than Symbol to a string
-    label = `${label}`;
-    const found = timeLogImpl(this, 'timeEnd', label);
-    trace(kTraceEnd, kTraceConsoleCategory, `time::${label}`, 0);
-    if (found) {
-      this._times.delete(label);
-    }
+    if (this[kInternalTimeLogImpl] === undefined)
+      this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
+
+    timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label);
   },
 
   timeLog(label = 'default', ...data) {
-    // Coerces everything other than Symbol to a string
-    label = `${label}`;
-    timeLogImpl(this, 'timeLog', label, data);
-    trace(kTraceInstant, kTraceConsoleCategory, `time::${label}`, 0);
+    if (this[kInternalTimeLogImpl] === undefined)
+      this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
+
+    timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, data);
   },
 
   trace: function trace(...args) {
@@ -515,9 +504,9 @@ const consoleMethods = {
 
     const _inspect = (v) => {
       const depth = v !== null &&
-                    typeof v === 'object' &&
-                    !isArray(v) &&
-                    ObjectKeys(v).length > 2 ? -1 : 0;
+        typeof v === 'object' &&
+        !isArray(v) &&
+        ObjectKeys(v).length > 2 ? -1 : 0;
       const opt = {
         depth,
         maxArrayLength: 3,
@@ -587,7 +576,7 @@ const consoleMethods = {
     for (; i < indexKeyArray.length; i++) {
       const item = tabularData[indexKeyArray[i]];
       const primitive = item === null ||
-          (typeof item !== 'function' && typeof item !== 'object');
+        (typeof item !== 'function' && typeof item !== 'object');
       if (properties === undefined && primitive) {
         hasPrimitives = true;
         valuesKeyArray[i] = _inspect(item);
@@ -596,7 +585,7 @@ const consoleMethods = {
         for (const key of keys) {
           map[key] ??= [];
           if ((primitive && properties) ||
-               !ObjectPrototypeHasOwnProperty(item, key))
+            !ObjectPrototypeHasOwnProperty(item, key))
             map[key][i] = '';
           else
             map[key][i] = _inspect(item[key]);
@@ -617,71 +606,14 @@ const consoleMethods = {
   },
 };
 
-// Returns true if label was found
-function timeLogImpl(self, name, label, data) {
-  const time = self._times.get(label);
-  if (time === undefined) {
-    process.emitWarning(`No such label '${label}' for console.${name}()`);
-    return false;
-  }
-  const duration = process.hrtime(time);
-  const ms = duration[0] * 1000 + duration[1] / 1e6;
-
-  const formatted = formatTime(ms);
-
-  if (data === undefined) {
-    self.log('%s: %s', label, formatted);
-  } else {
-    self.log('%s: %s', label, formatted, ...new SafeArrayIterator(data));
-  }
-  return true;
-}
-
-function pad(value) {
-  return StringPrototypePadStart(`${value}`, 2, '0');
-}
-
-function formatTime(ms) {
-  let hours = 0;
-  let minutes = 0;
-  let seconds = 0;
-
-  if (ms >= kSecond) {
-    if (ms >= kMinute) {
-      if (ms >= kHour) {
-        hours = MathFloor(ms / kHour);
-        ms = ms % kHour;
-      }
-      minutes = MathFloor(ms / kMinute);
-      ms = ms % kMinute;
-    }
-    seconds = ms / kSecond;
-  }
-
-  if (hours !== 0 || minutes !== 0) {
-    ({ 0: seconds, 1: ms } = StringPrototypeSplit(
-      NumberPrototypeToFixed(seconds, 3),
-      '.',
-    ));
-    const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes;
-    return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`;
-  }
-
-  if (seconds !== 0) {
-    return `${NumberPrototypeToFixed(seconds, 3)}s`;
-  }
-
-  return `${Number(NumberPrototypeToFixed(ms, 3))}ms`;
-}
-
 const keyKey = 'Key';
 const valuesKey = 'Values';
 const indexKey = '(index)';
 const iterKey = '(iteration index)';
 
 const isArray = (v) => ArrayIsArray(v) || isTypedArray(v) || isBuffer(v);
 
-function noop() {}
+function noop() { }
 
 for (const method of ReflectOwnKeys(consoleMethods))
   Console.prototype[method] = consoleMethods[method];
@@ -728,5 +660,4 @@ module.exports = {
   kBindStreamsLazy,
   kBindProperties,
   initializeGlobalConsole,
-  formatTime, // exported for tests
 };

lib/internal/modules/cjs/loader.js

@@ -61,7 +61,6 @@ const {
   StringPrototypeSplit,
   StringPrototypeStartsWith,
   Symbol,
-  Number,
 } = primordials;
 
 // Map used to store CJS parsing data or for ESM loading.
@@ -360,20 +359,15 @@ function setModuleParent(value) {
   moduleParentCache.set(this, value);
 }
 
-const { debuglog, isDebugEnabled } = require('internal/util/debuglog');
+const { debuglog, debugWithTimer } = require('internal/util/debuglog');
 
 let debug = debuglog('module', (fn) => {
   debug = fn;
 });
 
-let hrtimeBigIntTimingFn = () => {
-  hrtimeBigIntTimingFn = isDebugEnabled('timing_module_cjs') ? process.hrtime.bigint : () => 0;
-
-  return hrtimeBigIntTimingFn();
-};
-
-let debugTiming = debuglog('timing_module_cjs', (fn) => {
-  debugTiming = fn;
+let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => {
+  startTimer = start;
+  endTimer = end;
 });
 
 ObjectDefineProperty(Module.prototype, 'parent', {
@@ -971,10 +965,6 @@ function getExportsForCircularRequire(module) {
   return module.exports;
 }
 
-function logTiming(request, parent, start) {
-  debugTiming('[%s] [%s]: %d ms', parent?.id || '', request, Number((hrtimeBigIntTimingFn() - start)) / 1e6);
-}
-
 /**
  * Load a module from cache if it exists, otherwise create a new module instance.
  * 1. If a module already exists in the cache: return its exports object.
@@ -987,7 +977,9 @@ function logTiming(request, parent, start) {
  * @param {boolean} isMain Whether the module is the main entry point
  */
 Module._load = function(request, parent, isMain) {
-  const start = hrtimeBigIntTimingFn();
+  const label = `[${parent?.id || ''}] [${request}]`;
+
+  startTimer(label);
 
   let relResolveCacheIdentifier;
   if (parent) {
@@ -1005,12 +997,12 @@ Module._load = function(request, parent, isMain) {
         if (!cachedModule.loaded) {
           const result = getExportsForCircularRequire(cachedModule);
 
-          logTiming(request, parent, start);
+          endTimer(label);
 
           return result;
         }
 
-        logTiming(request, parent, start);
+        endTimer(label);
         return cachedModule.exports;
       }
       delete relativeResolveCache[relResolveCacheIdentifier];
@@ -1027,7 +1019,7 @@ Module._load = function(request, parent, isMain) {
 
     const module = loadBuiltinModule(id, request);
 
-    logTiming(request, parent, start);
+    endTimer(label);
     return module.exports;
   }
 
@@ -1040,21 +1032,21 @@ Module._load = function(request, parent, isMain) {
       if (!parseCachedModule || parseCachedModule.loaded) {
         const result = getExportsForCircularRequire(cachedModule);
 
-        logTiming(request, parent, start);
+        endTimer(label);
 
         return result;
       }
       parseCachedModule.loaded = true;
     } else {
-      logTiming(request, parent, start);
+      endTimer(label);
       return cachedModule.exports;
     }
   }
 
   if (BuiltinModule.canBeRequiredWithoutScheme(filename)) {
     const mod = loadBuiltinModule(filename, request);
 
-    logTiming(request, parent, start);
+    endTimer(label);
 
     return mod.exports;
   }
@@ -1103,7 +1095,7 @@ Module._load = function(request, parent, isMain) {
     }
   }
 
-  logTiming(request, parent, start);
+  endTimer(label);
 
   return module.exports;
 };