module: print amount of load time of a cjs module

lib/internal/modules/cjs/loader.js

@@ -61,6 +61,7 @@ const {
   StringPrototypeSplit,
   StringPrototypeStartsWith,
   Symbol,
+  Number,
 } = primordials;
 
 // Map used to store CJS parsing data or for ESM loading.
@@ -359,10 +360,22 @@ function setModuleParent(value) {
   moduleParentCache.set(this, value);
 }
 
-let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
+const { debuglog, isDebugEnabled } = require('internal/util/debuglog');
+
+let debug = debuglog('module', (fn) => {
   debug = fn;
 });
 
+let hrtimeBigIntTimingFn = () => {
+  hrtimeBigIntTimingFn = isDebugEnabled('trace_events') ? process.hrtime.bigint : () => 0;
+
+  return hrtimeBigIntTimingFn();
+};
+
+let debugTiming = debuglog('trace_events', (fn) => {
+  debugTiming = fn;
+});
+
 ObjectDefineProperty(Module.prototype, 'parent', {
   __proto__: null,
   get: pendingDeprecate(
@@ -958,6 +971,10 @@ 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.
@@ -966,10 +983,12 @@ 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) {
+  const start = hrtimeBigIntTimingFn();
+
   let relResolveCacheIdentifier;
   if (parent) {
     debug('Module._load REQUEST %s parent: %s', request, parent.id);
@@ -984,8 +1003,14 @@ Module._load = function(request, parent, isMain) {
       if (cachedModule !== undefined) {
         updateChildren(parent, cachedModule, true);
         if (!cachedModule.loaded) {
-          return getExportsForCircularRequire(cachedModule);
+          const result = getExportsForCircularRequire(cachedModule);
+
+          logTiming(request, parent, start);
+
+          return result;
         }
+
+        logTiming(request, parent, start);
         return cachedModule.exports;
       }
       delete relativeResolveCache[relResolveCacheIdentifier];
@@ -1001,6 +1026,8 @@ Module._load = function(request, parent, isMain) {
     }
 
     const module = loadBuiltinModule(id, request);
+
+    logTiming(request, parent, start);
     return module.exports;
   }
 
@@ -1011,16 +1038,24 @@ Module._load = function(request, parent, isMain) {
     if (!cachedModule.loaded) {
       const parseCachedModule = cjsSourceCache.get(cachedModule);
       if (!parseCachedModule || parseCachedModule.loaded) {
-        return getExportsForCircularRequire(cachedModule);
+        const result = getExportsForCircularRequire(cachedModule);
+
+        logTiming(request, parent, start);
+
+        return result;
       }
       parseCachedModule.loaded = true;
     } else {
+      logTiming(request, parent, start);
       return cachedModule.exports;
     }
   }
 
   if (BuiltinModule.canBeRequiredWithoutScheme(filename)) {
     const mod = loadBuiltinModule(filename, request);
+
+    logTiming(request, parent, start);
+
     return mod.exports;
   }
 
@@ -1068,6 +1103,8 @@ Module._load = function(request, parent, isMain) {
     }
   }
 
+  logTiming(request, parent, start);
+
   return module.exports;
 };
 

lib/internal/util/debuglog.js

@@ -115,7 +115,12 @@ function debuglog(set, cb) {
   return logger;
 }
 
+function isDebugEnabled(set) {
+  return testEnabled(set);
+}
+
 module.exports = {
   debuglog,
+  isDebugEnabled,
   initializeDebugEnv,
 };

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

@@ -0,0 +1,24 @@
+import { spawnPromisified } from '../common/index.mjs';
+import assert from 'node:assert';
+import { execPath } from 'node:process';
+import { it } from 'node:test';
+
+it('should print the timing information for cjs', async () => {
+  process.env.NODE_DEBUG = 'trace_events';
+  const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], {
+    env: {
+      NODE_DEBUG: 'trace_events',
+    },
+  });
+
+  assert.strictEqual(result.code, 0);
+  assert.strictEqual(result.signal, null);
+  assert.strictEqual(result.stdout, '');
+
+  const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]'));
+
+  assert.notStrictEqual(firstLine, undefined);
+  assert.ok(firstLine.includes('TRACE_EVENTS'), `Not found TRACE_EVENTS on ${firstLine}`);
+  assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`);
+  assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`);
+});