module: print amount of load time of a cjs module

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

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, 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.
@@ -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 */) {
@@ -373,6 +364,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));
@@ -393,31 +392,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) {
@@ -611,63 +600,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)';
@@ -722,5 +654,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,
@@ -189,6 +190,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 };
@@ -210,12 +218,30 @@ function internalRequire(module, id) {
   }
   requireDepth++;
   try {
-    return Module._load(id, module, /* isMain */ false);
+    return wrapModuleLoad(id, module, /* isMain */ false);
   } finally {
     requireDepth--;
   }
 }
 
+/*
+ * 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
@@ -392,7 +418,7 @@ function setModuleParent(value) {
   this[kModuleParent] = value;
 }
 
-let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
+let debug = debuglog('module', (fn) => {
   debug = fn;
 });
 
@@ -1010,7 +1036,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) {
@@ -1308,7 +1334,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

@@ -160,8 +160,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) {