module: print amount of load time of a module

Author: H4ad

lib/internal/modules/cjs/loader.js

@@ -106,6 +106,7 @@ const {
 const assert = require('internal/assert');
 const fs = require('fs');
 const path = require('path');
+const { performance } = require('perf_hooks');
 const { internalModuleStat } = internalBinding('fs');
 const { safeGetenv } = internalBinding('credentials');
 const {
@@ -966,10 +967,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 = performance.now();
+
   let relResolveCacheIdentifier;
   if (parent) {
     debug('Module._load REQUEST %s parent: %s', request, parent.id);
@@ -984,8 +987,14 @@ Module._load = function(request, parent, isMain) {
       if (cachedModule !== undefined) {
         updateChildren(parent, cachedModule, true);
         if (!cachedModule.loaded) {
-          return getExportsForCircularRequire(cachedModule);
+          const result = getExportsForCircularRequire(cachedModule);
+
+          debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
+
+          return result;
         }
+
+        debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
         return cachedModule.exports;
       }
       delete relativeResolveCache[relResolveCacheIdentifier];
@@ -1001,6 +1010,8 @@ Module._load = function(request, parent, isMain) {
     }
 
     const module = loadBuiltinModule(id, request);
+
+    debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
     return module.exports;
   }
 
@@ -1011,16 +1022,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);
+
+        debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
+
+        return result;
       }
       parseCachedModule.loaded = true;
     } else {
+      debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
       return cachedModule.exports;
     }
   }
 
   if (BuiltinModule.canBeRequiredWithoutScheme(filename)) {
     const mod = loadBuiltinModule(filename, request);
+
+    debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
+
     return mod.exports;
   }
 
@@ -1068,6 +1087,8 @@ Module._load = function(request, parent, isMain) {
     }
   }
 
+  debug('TIMING [%s] [%s]: %d ms', parent?.id || '', request, performance.now() - start);
+
   return module.exports;
 };