module: print amount of load time of a cjs module

PR-URL: https://github.com/nodejs/node/pull/52213
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

lib/internal/console/constructor.js

@@ -13,9 +13,6 @@ const {
   Boolean,
   ErrorCaptureStackTrace,
   FunctionPrototypeBind,
-  MathFloor,
-  Number,
-  NumberPrototypeToFixed,
   ObjectDefineProperties,
   ObjectDefineProperty,
   ObjectKeys,
@@ -30,10 +27,8 @@ const {
   SafeSet,
   SafeWeakMap,
   StringPrototypeIncludes,
-  StringPrototypePadStart,
   StringPrototypeRepeat,
   StringPrototypeSlice,
-  StringPrototypeSplit,
   Symbol,
   SymbolHasInstance,
   SymbolToStringTag,
@@ -63,19 +58,14 @@ 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 { styleText } = require('util');
 const kCounts = Symbol('counts');
+const { time, timeLog, timeEnd, kNone } = require('internal/util/debuglog');
 
 const kTraceConsoleCategory = 'node,node.console';
 
-const kSecond = 1000;
-const kMinute = 60 * kSecond;
-const kHour = 60 * kMinute;
 const kMaxGroupIndentation = 1000;
 
 // Lazy loaded for startup performance.
@@ -101,6 +91,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 */) {
@@ -381,6 +372,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));
@@ -404,31 +403,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()', kNone, label, `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()', kNone, this[kInternalTimeLogImpl], label, `time::${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()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data);
   },
 
   trace: function trace(...args) {
@@ -627,63 +616,6 @@ 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)';
@@ -743,5 +675,4 @@ module.exports = {
   kBindStreamsLazy,
   kBindProperties,
   initializeGlobalConsole,
-  formatTime, // exported for tests
 };

lib/internal/main/repl.js

@@ -24,8 +24,7 @@ markBootstrapComplete();
 
 if (process.env.NODE_REPL_EXTERNAL_MODULE) {
   require('internal/modules/cjs/loader')
-    .Module
-    ._load(process.env.NODE_REPL_EXTERNAL_MODULE, undefined, true);
+    .wrapModuleLoad(process.env.NODE_REPL_EXTERNAL_MODULE, undefined, true);
 } else {
   // --input-type flag not supported in REPL
   if (getOptionValue('--input-type')) {

lib/internal/modules/cjs/loader.js

@@ -108,6 +108,7 @@ module.exports = {
   initializeCJS,
   Module,
   wrapSafe,
+  wrapModuleLoad,
   kIsMainSymbol,
   kIsCachedByESMLoader,
   kRequiredModuleSymbol,
@@ -181,6 +182,13 @@ const {
   isProxy,
 } = require('internal/util/types');
 
+const { debuglog, debugWithTimer } = require('internal/util/debuglog');
+
+let { startTimer, endTimer } = debugWithTimer('module_timer', (start, end) => {
+  startTimer = start;
+  endTimer = end;
+});
+
 const isWindows = process.platform === 'win32';
 
 const relativeResolveCache = { __proto__: null };
@@ -189,6 +197,24 @@ let requireDepth = 0;
 let isPreloading = false;
 let statCache = null;
 
+/**
+ * Internal method to add tracing capabilities for Module._load.
+ *
+ * See more {@link Module._load}
+ */
+function wrapModuleLoad(request, parent, isMain) {
+  const logLabel = `[${parent?.id || ''}] [${request}]`;
+  const traceLabel = `require('${request}')`;
+
+  startTimer(logLabel, traceLabel);
+
+  try {
+    return Module._load(request, parent, isMain);
+  } finally {
+    endTimer(logLabel, traceLabel);
+  }
+}
+
 /**
  * Get a path's properties, using an in-memory cache to minimize lookups.
  * @param {string} filename Absolute path to the file
@@ -354,7 +380,7 @@ function setModuleParent(value) {
   this[kModuleParent] = value;
 }
 
-let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
+let debug = debuglog('module', (fn) => {
   debug = fn;
 });
 
@@ -971,7 +997,7 @@ function getExportsForCircularRequire(module) {
  * 3. Otherwise, create a new module for the file and save it to the cache.
  *    Then have it load the file contents before returning its exports object.
  * @param {string} request Specifier of module to load via `require`
- * @param {string} parent Absolute path of the module importing the child
+ * @param {Module} parent Absolute path of the module importing the child
  * @param {boolean} isMain Whether the module is the main entry point
  */
 Module._load = function(request, parent, isMain) {
@@ -1268,7 +1294,7 @@ Module.prototype.require = function(id) {
   }
   requireDepth++;
   try {
-    return Module._load(id, this, /* isMain */ false);
+    return wrapModuleLoad(id, this, /* isMain */ false);
   } finally {
     requireDepth--;
   }

lib/internal/modules/esm/translators.js

@@ -43,6 +43,7 @@ const {
 const {
   kIsCachedByESMLoader,
   Module: CJSModule,
+  wrapModuleLoad,
   kModuleSource,
   kModuleExport,
   kModuleExportNames,
@@ -197,7 +198,7 @@ function loadCJSModule(module, source, url, filename, isMain) {
           importAttributes = { __proto__: null, type: 'json' };
           break;
         case '.node':
-          return CJSModule._load(specifier, module);
+          return wrapModuleLoad(specifier, module);
         default:
             // fall through
       }
@@ -289,7 +290,7 @@ translators.set('commonjs-sync', function requireCommonJS(url, source, isMain) {
   return createCJSModuleWrap(url, source, isMain, (module, source, url, filename, isMain) => {
     assert(module === CJSModule._cache[filename]);
     assert(!isMain);
-    CJSModule._load(filename, null, isMain);
+    wrapModuleLoad(filename, null, isMain);
   });
 });
 
@@ -314,7 +315,7 @@ translators.set('commonjs', async function commonjsStrategy(url, source,
   // obtained by calling the monkey-patchable CJS loader.
   const cjsLoader = source == null ? (module, source, url, filename, isMain) => {
     assert(module === CJSModule._cache[filename]);
-    CJSModule._load(filename, undefined, isMain);
+    wrapModuleLoad(filename, undefined, isMain);
   } : loadCJSModule;
 
   try {

lib/internal/modules/run_main.js

@@ -154,8 +154,8 @@ function executeUserEntryPoint(main = process.argv[1]) {
   // try to run the entry point via the CommonJS loader; and if that fails under certain conditions, retry as ESM.
   if (!useESMLoader) {
     const cjsLoader = require('internal/modules/cjs/loader');
-    const { Module } = cjsLoader;
-    Module._load(main, null, true);
+    const { wrapModuleLoad } = cjsLoader;
+    wrapModuleLoad(main, null, true);
   } else {
     const mainPath = resolvedMain || main;
     if (mainURL === undefined) {

lib/internal/util/debuglog.js

@@ -1,15 +1,26 @@
 'use strict';
 
 const {
+  MathFloor,
+  Number,
+  NumberPrototypeToFixed,
   ObjectDefineProperty,
   RegExp,
   RegExpPrototypeExec,
   SafeArrayIterator,
+  SafeMap,
+  StringPrototypePadStart,
+  StringPrototypeSplit,
   StringPrototypeToLowerCase,
   StringPrototypeToUpperCase,
 } = primordials;
-
+const {
+  CHAR_LOWERCASE_B: kTraceBegin,
+  CHAR_LOWERCASE_E: kTraceEnd,
+  CHAR_LOWERCASE_N: kTraceInstant,
+} = require('internal/constants');
 const { inspect, format, formatWithOptions } = require('internal/util/inspect');
+const { isTraceCategoryEnabled, trace } = internalBinding('trace_events');
 
 // `debugImpls` and `testEnabled` are deliberately not initialized so any call
 // to `debuglog()` before `initializeDebugEnv()` is called will throw.
@@ -51,7 +62,7 @@ function lazyUtilColors() {
   return utilColors;
 }
 
-function debuglogImpl(enabled, set) {
+function debuglogImpl(enabled, set, args) {
   if (debugImpls[set] === undefined) {
     if (enabled) {
       const pid = process.pid;
@@ -115,7 +126,371 @@ function debuglog(set, cb) {
   return logger;
 }
 
+function pad(value) {
+  return StringPrototypePadStart(`${value}`, 2, '0');
+}
+
+const kNone = 1 << 0;
+const kSkipLog = 1 << 1;
+const kSkipTrace = 1 << 2;
+
+const kSecond = 1000;
+const kMinute = 60 * kSecond;
+const kHour = 60 * kMinute;
+
+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`;
+}
+
+function safeTraceLabel(label) {
+  return label.replace(/\\/g, '\\\\');
+}
+
+/**
+ * @typedef {(label: string, timeFormatted: string, args?: any[]) => void} LogImpl
+ */
+
+/**
+ * Returns true if label was found
+ * @param {string} timesStore
+ * @param {string} implementation
+ * @param {LogImpl} logImp
+ * @param {string} label
+ * @param {any} args
+ * @returns {void}
+ */
+function timeLogImpl(timesStore, implementation, logImp, label, args) {
+  const time = timesStore.get(label);
+  if (time === undefined) {
+    process.emitWarning(`No such label '${label}' for ${implementation}`);
+    return;
+  }
+
+  const duration = process.hrtime(time);
+  const ms = duration[0] * 1000 + duration[1] / 1e6;
+
+  const formatted = formatTime(ms);
+
+  if (args === undefined) {
+    logImp(label, formatted);
+  } else {
+    logImp(label, formatted, args);
+  }
+}
+
+/**
+ * @param {SafeMap} timesStore
+ * @param {string} traceCategory
+ * @param {string} implementation
+ * @param {number} timerFlags
+ * @param {string} logLabel
+ * @param {string} traceLabel
+ * @returns {void}
+ */
+function time(timesStore, traceCategory, implementation, timerFlags, logLabel = 'default', traceLabel = undefined) {
+  // Coerces everything other than Symbol to a string
+  logLabel = `${logLabel}`;
+
+  if (traceLabel !== undefined) {
+    traceLabel = `${traceLabel}`;
+  } else {
+    traceLabel = logLabel;
+  }
+
+  if (timesStore.has(logLabel)) {
+    process.emitWarning(`Label '${logLabel}' already exists for ${implementation}`);
+    return;
+  }
+
+  if ((timerFlags & kSkipTrace) === 0) {
+    traceLabel = safeTraceLabel(traceLabel);
+    trace(kTraceBegin, traceCategory, traceLabel, 0);
+  }
+
+  timesStore.set(logLabel, process.hrtime());
+}
+
+/**
+ * @param {SafeMap} timesStore
+ * @param {string} traceCategory
+ * @param {string} implementation
+ * @param {number} timerFlags
+ * @param {LogImpl} logImpl
+ * @param {string} logLabel
+ * @param {string} traceLabel
+ * @returns {void}
+ */
+function timeEnd(
+  timesStore,
+  traceCategory,
+  implementation,
+  timerFlags,
+  logImpl,
+  logLabel = 'default',
+  traceLabel = undefined,
+) {
+  // Coerces everything other than Symbol to a string
+  logLabel = `${logLabel}`;
+
+  if (traceLabel !== undefined) {
+    traceLabel = `${traceLabel}`;
+  } else {
+    traceLabel = logLabel;
+  }
+
+  if ((timerFlags & kSkipLog) === 0) {
+    timeLogImpl(timesStore, implementation, logImpl, logLabel);
+  }
+
+  if ((timerFlags & kSkipTrace) === 0) {
+    traceLabel = safeTraceLabel(traceLabel);
+    trace(kTraceEnd, traceCategory, traceLabel, 0);
+  }
+
+  timesStore.delete(logLabel);
+}
+
+/**
+ * @param {SafeMap} timesStore
+ * @param {string} traceCategory
+ * @param {string} implementation
+ * @param {number} timerFlags
+ * @param {LogImpl} logImpl
+ * @param {string} logLabel
+ * @param {string} traceLabel
+ * @param {any[]} args
+ * @returns {void}
+ */
+function timeLog(
+  timesStore,
+  traceCategory,
+  implementation,
+  timerFlags,
+  logImpl,
+  logLabel = 'default',
+  traceLabel = undefined,
+  args,
+) {
+  // Coerces everything other than Symbol to a string
+  logLabel = `${logLabel}`;
+
+  if (traceLabel !== undefined) {
+    traceLabel = `${traceLabel}`;
+  } else {
+    traceLabel = logLabel;
+  }
+
+  if ((timerFlags & kSkipLog) === 0) {
+    timeLogImpl(timesStore, implementation, logImpl, logLabel, args);
+  }
+
+  if ((timerFlags & kSkipTrace) === 0) {
+    traceLabel = safeTraceLabel(traceLabel);
+    trace(kTraceInstant, traceCategory, traceLabel, 0);
+  }
+}
+
+/**
+ * @type {Record<string, SafeMap>}
+ */
+let tracesStores;
+
+/**
+ * @typedef {(logLabel: string, traceLabel?: string) => void} TimerStart
+ */
+
+/**
+ * @typedef {(logLabel: string, traceLabel?: string) => void} TimerEnd
+ */
+
+/**
+ * @typedef {(logLabel: string, traceLabel?: string, args?: any[]) => void} TimerLog
+ */
+
+/**
+ * Debuglog with time fns and support for trace
+ * @param {string} set
+ * @param {(startTimer: TimerStart, endTimer: TimerEnd, logTimer: TimerLog) => void} cb
+ * @returns {{startTimer: TimerStart, endTimer: TimerEnd, logTimer: TimerLog}}
+ */
+function debugWithTimer(set, cb) {
+  set = StringPrototypeToUpperCase(set);
+
+  if (tracesStores === undefined) {
+    tracesStores = { __proto__: null };
+  }
+
+  /**
+   * @type {LogImpl}
+   */
+  function logImpl(label, timeFormatted, args) {
+    const pid = process.pid;
+    const colors = { colors: lazyUtilColors().shouldColorize(process.stderr) };
+    const coloredPID = inspect(pid, colors);
+
+    if (args === undefined)
+      process.stderr.write(format('%s %s %s: %s\n', set, coloredPID, label, timeFormatted));
+    else
+      process.stderr.write(
+        format(
+          '%s %s %s: %s\n',
+          set,
+          coloredPID,
+          label,
+          timeFormatted,
+          ...new SafeArrayIterator(args),
+        ),
+      );
+  }
+
+  const kTraceCategory = `node,node.${StringPrototypeToLowerCase(set)}`;
+  let debugLogCategoryEnabled = false;
+  let traceCategoryEnabled = false;
+  let timerFlags = kNone;
+
+  /**
+   * @type {TimerStart}
+   */
+  function internalStartTimer(logLabel, traceLabel) {
+    time(
+      tracesStores[set],
+      kTraceCategory,
+      'debuglog.time',
+      timerFlags,
+      logLabel,
+      traceLabel,
+    );
+  }
+
+  /**
+   * @type {TimerEnd}
+   */
+  function internalEndTimer(logLabel, traceLabel) {
+    timeEnd(
+      tracesStores[set],
+      kTraceCategory,
+      'debuglog.timeEnd',
+      timerFlags,
+      logImpl,
+      logLabel,
+      traceLabel,
+    );
+  }
+
+  /**
+   * @type {TimerLog}
+   */
+  function internalLogTimer(logLabel, traceLabel, args) {
+    timeLog(
+      tracesStores[set],
+      kTraceCategory,
+      'debuglog.timeLog',
+      timerFlags,
+      logImpl,
+      logLabel,
+      traceLabel,
+      args,
+    );
+  }
+
+  function init() {
+    if (tracesStores[set] === undefined) {
+      tracesStores[set] = new SafeMap();
+    }
+    emitWarningIfNeeded(set);
+    debugLogCategoryEnabled = testEnabled(set);
+    traceCategoryEnabled = isTraceCategoryEnabled(kTraceCategory);
+
+    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);
+  }
+
+  /**
+   * @type {TimerStart}
+   */
+  const startTimer = (logLabel, traceLabel) => {
+    init();
+
+    if (debugLogCategoryEnabled || traceCategoryEnabled)
+      internalStartTimer(logLabel, traceLabel);
+  };
+
+  /**
+   * @type {TimerEnd}
+   */
+  const endTimer = (logLabel, traceLabel) => {
+    init();
+
+    if (debugLogCategoryEnabled || traceCategoryEnabled)
+      internalEndTimer(logLabel, traceLabel);
+  };
+
+  /**
+   * @type {TimerLog}
+   */
+  const logTimer = (logLabel, traceLabel, args) => {
+    init();
+
+    if (debugLogCategoryEnabled || traceCategoryEnabled)
+      internalLogTimer(logLabel, traceLabel, args);
+  };
+
+  return {
+    startTimer,
+    endTimer,
+    logTimer,
+  };
+}
+
 module.exports = {
+  kNone,
+  kSkipLog,
+  kSkipTrace,
+  formatTime,
+  time,
+  timeEnd,
+  timeLog,
   debuglog,
+  debugWithTimer,
   initializeDebugEnv,
 };

test/fixtures/console/console.snapshot

@@ -6,3 +6,4 @@ Trace: foo
     at *
     at *
     at *
+    at *

test/fixtures/errors/force_colors.snapshot

@@ -10,5 +10,6 @@ Error: Should include grayed stack trace
     at *
     at *
     at *
+    at *
 
 Node.js *

test/fixtures/errors/promise_always_throw_unhandled.snapshot

@@ -12,5 +12,6 @@ Error: One
     at *
     at *
     at *
+    at *
 
 Node.js *

test/fixtures/errors/promise_unhandled_warn_with_error.snapshot

@@ -6,5 +6,6 @@
     at *
     at *
     at *
+    at *
 (Use `node --trace-warnings ...` to show where the warning was created)
 (node:*) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https:*nodejs.org*api*cli.html#cli_unhandled_rejections_mode). (rejection id: 1)

test/fixtures/errors/unhandled_promise_trace_warnings.snapshot

@@ -10,6 +10,7 @@
     at *
     at *
     at *
+    at *
 (node:*) Error: This was rejected
     at *
     at *
@@ -18,6 +19,7 @@
     at *
     at *
     at *
+    at *
 (node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1)
     at *
     at *

test/fixtures/test-runner/output/abort.snapshot

@@ -135,6 +135,7 @@ not ok 2 - promise abort signal
     *
     *
     *
+    *
   ...
 # Subtest: callback timeout signal
     # Subtest: ok 1
@@ -272,6 +273,7 @@ not ok 4 - callback abort signal
     *
     *
     *
+    *
   ...
 1..4
 # tests 22

test/fixtures/test-runner/output/abort_suite.snapshot

@@ -137,6 +137,7 @@ not ok 2 - describe abort signal
     *
     *
     *
+    *
   ...
 1..2
 # tests 9

test/message/assert_throws_stack.out

@@ -15,6 +15,7 @@ AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal:
     at *
     at *
     at *
+    at *
     at * {
   generatedMessage: true,
   code: 'ERR_ASSERTION',

test/message/internal_assert.out

@@ -12,6 +12,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss
     at *
     at *
     at *
+    at *
     at * {
   code: 'ERR_INTERNAL_ASSERTION'
 }

test/message/internal_assert_fail.out

@@ -13,6 +13,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss
     at *
     at *
     at *
+    at *
     at * {
   code: 'ERR_INTERNAL_ASSERTION'
 }

test/message/util-inspect-error-cause.out

@@ -5,6 +5,7 @@ Error: Number error cause
     at *
     at *
     at *
+    at *
     at * {
   [cause]: 42
 }
@@ -15,6 +16,7 @@ Error: Object cause
     at *
     at *
     at *
+    at *
     at * {
   [cause]: {
     message: 'Unique',
@@ -30,6 +32,7 @@ Error: undefined cause
     at *
     at *
     at *
+    at *
     at * {
   [cause]: undefined
 }
@@ -40,6 +43,7 @@ Error: cause that throws
     at *
     at *
     at *
+    at *
     at * {
   [cause]: [Getter]
 }
@@ -49,7 +53,7 @@ RangeError: New Stack Frames
   [cause]: FoobarError: Individual message
       at *
   *[90m    at *[39m
-  *[90m    ... 4 lines matching cause stack trace ...*[39m
+  *[90m    ... 5 lines matching cause stack trace ...*[39m
   *[90m    at *[39m {
     status: *[32m'Feeling good'*[39m,
     extraProperties: *[32m'Yes!'*[39m,
@@ -61,17 +65,18 @@ RangeError: New Stack Frames
     *[90m    at *[39m
     *[90m    at *[39m
     *[90m    at *[39m
+    *[90m    at *[39m
   }
 }
 Error: Stack causes
     at *
 *[90m    at *[39m
-*[90m    ... 4 lines matching cause stack trace ...*[39m
+*[90m    ... 5 lines matching cause stack trace ...*[39m
 *[90m    at *[39m {
   [cause]: FoobarError: Individual message
       at *
   *[90m    at *[39m
-  *[90m    ... 4 lines matching cause stack trace ...*[39m
+  *[90m    ... 5 lines matching cause stack trace ...*[39m
   *[90m    at *[39m {
     status: *[32m'Feeling good'*[39m,
     extraProperties: *[32m'Yes!'*[39m,
@@ -83,6 +88,7 @@ Error: Stack causes
     *[90m    at *[39m
     *[90m    at *[39m
     *[90m    at *[39m
+    *[90m    at *[39m
   }
 }
 RangeError: New Stack Frames
@@ -91,12 +97,12 @@ RangeError: New Stack Frames
   [cause]: Error: Stack causes
       at *
   *[90m    at *[39m
-  *[90m    ... 4 lines matching cause stack trace ...*[39m
+  *[90m    ... 5 lines matching cause stack trace ...*[39m
   *[90m    at *[39m {
     [cause]: FoobarError: Individual message
         at *
     *[90m    at *[39m
-    *[90m    ... 4 lines matching cause stack trace ...*[39m
+    *[90m    ... 5 lines matching cause stack trace ...*[39m
     *[90m    at *[39m {
       status: *[32m'Feeling good'*[39m,
       extraProperties: *[32m'Yes!'*[39m,
@@ -108,6 +114,7 @@ RangeError: New Stack Frames
       *[90m    at *[39m
       *[90m    at *[39m
       *[90m    at *[39m
+      *[90m    at *[39m
     }
   }
 }
@@ -117,7 +124,7 @@ RangeError: New Stack Frames
   [cause]: FoobarError: Individual message
       at *
       at *
-      ... 4 lines matching cause stack trace ...
+      ... 5 lines matching cause stack trace ...
       at * {
     status: 'Feeling good',
     extraProperties: 'Yes!',
@@ -129,17 +136,18 @@ RangeError: New Stack Frames
         at *
         at *
         at *
+        at *
   }
 }
 Error: Stack causes
     at *
     at *
-    ... 4 lines matching cause stack trace ...
+    ... 5 lines matching cause stack trace ...
     at * {
   [cause]: FoobarError: Individual message
       at *
       at *
-      ... 4 lines matching cause stack trace ...
+      ... 5 lines matching cause stack trace ...
       at *
     status: 'Feeling good',
     extraProperties: 'Yes!',
@@ -151,6 +159,7 @@ Error: Stack causes
         at *
         at *
         at *
+        at *
   }
 }
 RangeError: New Stack Frames
@@ -159,12 +168,12 @@ RangeError: New Stack Frames
   [cause]: Error: Stack causes
       at *
       at *
-      ... 4 lines matching cause stack trace ...
+      ... 5 lines matching cause stack trace ...
       at * {
     [cause]: FoobarError: Individual message
         at *
         at *
-        ... 4 lines matching cause stack trace ...
+        ... 5 lines matching cause stack trace ...
         at * {
       status: 'Feeling good',
       extraProperties: 'Yes!',
@@ -176,6 +185,7 @@ RangeError: New Stack Frames
           at *
           at *
           at *
+          at *
     }
   }
 }

test/message/util_inspect_error.out

@@ -8,6 +8,7 @@
        at *
        at *
        at *
+       at *
   nested:
    { err:
       Error: foo
@@ -19,6 +20,7 @@
           at *
           at *
           at *
+          at *
 {
   err: Error: foo
   bar
@@ -29,6 +31,7 @@
       at *
       at *
       at *
+      at *
   nested: {
     err: Error: foo
     bar
@@ -39,6 +42,7 @@
         at *
         at *
         at *
+        at *
   }
 }
 { Error: foo
@@ -50,4 +54,5 @@ bar
     at *
     at *
     at *
+    at *
   foo: 'bar' }

test/parallel/test-console-formatTime.js

@@ -1,7 +1,7 @@
 'use strict';
 // Flags: --expose-internals
 require('../common');
-const { formatTime } = require('internal/console/constructor');
+const { formatTime } = require('internal/util/debuglog');
 const assert = require('assert');
 
 assert.strictEqual(formatTime(100.0096), '100.01ms');

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

@@ -0,0 +1,95 @@
+import '../common/index.mjs';
+import assert from 'node:assert';
+import { readFile } from 'node:fs/promises';
+import { it } from 'node:test';
+import tmpdir from '../common/tmpdir.js';
+import { spawnSyncAndAssert } from '../common/child_process.js';
+
+tmpdir.refresh();
+
+it('should print the timing information for cjs', () => {
+  const result = spawnSyncAndAssert(process.execPath, ['--eval', 'require("url");'], {
+    cwd: tmpdir.path,
+    env: {
+      ...process.env,
+      NODE_DEBUG: 'module_timer',
+    },
+  }, {
+    stdout: '',
+    stderr: (result) => result.includes('MODULE_TIMER'),
+  });
+
+  const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
+
+  assert.notStrictEqual(firstLine, undefined);
+  assert.ok(firstLine.includes('MODULE_TIMER'), `Not found MODULE_TIMER on ${firstLine}`);
+  assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`);
+  assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`);
+});
+
+it('should write tracing information for cjs', async () => {
+  const outputFile = tmpdir.resolve('output-trace.log');
+
+  spawnSyncAndAssert(process.execPath, [
+    '--trace-event-categories',
+    'node.module_timer',
+    '--trace-event-file-pattern',
+    outputFile,
+    '--eval',
+    'require("url");',
+  ], {
+    cwd: tmpdir.path,
+  }, {
+    stdout: '',
+    stderr: '',
+  });
+
+  const expectedMimeTypes = ['b', 'e'];
+  const outputFileContent = await readFile(outputFile, 'utf-8');
+  const outputFileJson = JSON.parse(outputFileContent).traceEvents;
+  const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')");
+
+  assert.strictEqual(urlTraces.length, 2);
+
+  for (const trace of urlTraces) {
+    assert.strictEqual(trace.ph, expectedMimeTypes.shift());
+  }
+});
+
+it('should write tracing & print logs for cjs', async () => {
+  const outputFile = tmpdir.resolve('output-trace-and-log.log');
+
+  const result = spawnSyncAndAssert(process.execPath, [
+    '--trace-event-categories',
+    'node.module_timer',
+    '--trace-event-file-pattern',
+    outputFile,
+    '--eval',
+    'require("url");',
+  ], {
+    cwd: tmpdir.path,
+    env: {
+      ...process.env,
+      NODE_DEBUG: 'module_timer',
+    },
+  }, {
+    stdout: '',
+    stderr: (result) => result.includes('MODULE_TIMER'),
+  });
+
+  const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
+
+  assert.notStrictEqual(firstLine, undefined);
+  assert.ok(firstLine.includes('MODULE_TIMER'), `Not found MODULE_TIMER on ${firstLine}`);
+  assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`);
+  assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`);
+
+  const expectedMimeTypes = ['b', 'e'];
+  const outputFileContent = await readFile(outputFile, 'utf-8');
+  const outputFileJson = JSON.parse(outputFileContent).traceEvents;
+  const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')");
+
+  for (const trace of urlTraces) {
+    assert.strictEqual(trace.ph, expectedMimeTypes.shift());
+  }
+});

test/parallel/test-repl.js

@@ -581,6 +581,7 @@ const errorTests = [
       /^ {4}at .*/,
       /^ {4}at .*/,
       /^ {4}at .*/,
+      /^ {4}at .*/,
       "  code: 'MODULE_NOT_FOUND',",
       "  requireStack: [ '<repl>' ]",
       '}',

test/parallel/test-trace-events-console.js

@@ -10,6 +10,7 @@ const tmpdir = require('../common/tmpdir');
 
 const names = [
   'time::foo',
+  'time::\\winvalid_char',
   'count::bar',
 ];
 const expectedCounts = [ 1, 2, 0 ];
@@ -21,8 +22,10 @@ if (process.argv[2] === 'child') {
   console.count('bar');
   console.count('bar');
   console.countReset('bar');
+  console.time('\\winvalid_char');
   console.time('foo');
   setImmediate(() => {
+    console.timeEnd('\\winvalid_char');
     console.timeLog('foo');
     setImmediate(() => {
       console.timeEnd('foo');

test/pseudo-tty/console_colors.out

@@ -12,6 +12,7 @@ foobar
 [90m    at *[39m
 [90m    at *[39m
 [90m    at *[39m
+[90m    at *[39m
 
 Error: Should not ever get here.
     at Object.<anonymous> [90m(*node_modules*[4m*node_modules*[24m*bar.js:*:*[90m)[39m
@@ -21,8 +22,8 @@ Error: Should not ever get here.
 [90m    at *[39m
 [90m    at *[39m
 [90m    at *[39m
-    at Object.<anonymous> [90m(*console_colors.js:*:*[90m)[39m
 [90m    at *[39m
+    at Object.<anonymous> [90m(*console_colors.js:*:*[90m)[39m
 [90m    at *[39m
 
 Error

test/pseudo-tty/test-fatal-error.out

@@ -8,6 +8,7 @@ TypeError: foobar
 [90m    at *(node:internal*loader:*:*)[39m
 [90m    at *(node:internal*loader:*:*)[39m
 [90m    at *(node:internal*loader:*:*)[39m
+[90m    at *(node:internal*loader:*:*)[39m
 [90m    at *[39m
 [90m    at *[39m {
   bla: [33mtrue[39m

test/pseudo-tty/test-trace-sigint.out

@@ -7,3 +7,4 @@ KEYBOARD_INTERRUPT: Script execution was interrupted by `SIGINT`
     at *
     at *
     at *
+    at *