Skip to content

Commit 49aa68e

Browse files
H4adjoyeecheung
H4ad
authored and
joyeecheung
committed
module: print amount of load time of a cjs module
PR-URL: #52213 Reviewed-By: Joyee Cheung <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Matteo Collina <[email protected]>
1 parent d56bfc6 commit 49aa68e

25 files changed

+574
-113
lines changed

‎lib/internal/console/constructor.js

+19-88
Original file line numberDiff line numberDiff line change
@@ -12,9 +12,6 @@ const {
1212
Boolean,
1313
ErrorCaptureStackTrace,
1414
FunctionPrototypeBind,
15-
MathFloor,
16-
Number,
17-
NumberPrototypeToFixed,
1815
ObjectDefineProperties,
1916
ObjectDefineProperty,
2017
ObjectKeys,
@@ -29,10 +26,8 @@ const {
2926
SafeWeakMap,
3027
SafeSet,
3128
StringPrototypeIncludes,
32-
StringPrototypePadStart,
3329
StringPrototypeRepeat,
3430
StringPrototypeSlice,
35-
StringPrototypeSplit,
3631
Symbol,
3732
SymbolHasInstance,
3833
SymbolToStringTag,
@@ -62,18 +57,13 @@ const {
6257
isTypedArray, isSet, isMap, isSetIterator, isMapIterator,
6358
} = require('internal/util/types');
6459
const {
65-
CHAR_LOWERCASE_B: kTraceBegin,
66-
CHAR_LOWERCASE_E: kTraceEnd,
67-
CHAR_LOWERCASE_N: kTraceInstant,
6860
CHAR_UPPERCASE_C: kTraceCount,
6961
} = require('internal/constants');
7062
const kCounts = Symbol('counts');
63+
const { time, timeLog, timeEnd, kNone } = require('internal/util/debuglog');
7164

7265
const kTraceConsoleCategory = 'node,node.console';
7366

74-
const kSecond = 1000;
75-
const kMinute = 60 * kSecond;
76-
const kHour = 60 * kMinute;
7767
const kMaxGroupIndentation = 1000;
7868

7969
// Lazy loaded for startup performance.
@@ -99,6 +89,7 @@ const kBindStreamsEager = Symbol('kBindStreamsEager');
9989
const kBindStreamsLazy = Symbol('kBindStreamsLazy');
10090
const kUseStdout = Symbol('kUseStdout');
10191
const kUseStderr = Symbol('kUseStderr');
92+
const kInternalTimeLogImpl = Symbol('kInternalTimeLogImpl');
10293

10394
const optionsMap = new SafeWeakMap();
10495
function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
@@ -373,6 +364,14 @@ function createWriteErrorHandler(instance, streamSymbol) {
373364
};
374365
}
375366

367+
function timeLogImpl(label, formatted, args) {
368+
if (args === undefined) {
369+
this.log('%s: %s', label, formatted);
370+
} else {
371+
this.log('%s: %s', label, formatted, ...new SafeArrayIterator(args));
372+
}
373+
}
374+
376375
const consoleMethods = {
377376
log(...args) {
378377
this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args));
@@ -393,31 +392,21 @@ const consoleMethods = {
393392
},
394393

395394
time(label = 'default') {
396-
// Coerces everything other than Symbol to a string
397-
label = `${label}`;
398-
if (this._times.has(label)) {
399-
process.emitWarning(`Label '${label}' already exists for console.time()`);
400-
return;
401-
}
402-
trace(kTraceBegin, kTraceConsoleCategory, `time::${label}`, 0);
403-
this._times.set(label, process.hrtime());
395+
time(this._times, kTraceConsoleCategory, 'console.time()', kNone, label, `time::${label}`);
404396
},
405397

406398
timeEnd(label = 'default') {
407-
// Coerces everything other than Symbol to a string
408-
label = `${label}`;
409-
const found = timeLogImpl(this, 'timeEnd', label);
410-
trace(kTraceEnd, kTraceConsoleCategory, `time::${label}`, 0);
411-
if (found) {
412-
this._times.delete(label);
413-
}
399+
if (this[kInternalTimeLogImpl] === undefined)
400+
this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
401+
402+
timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`);
414403
},
415404

416405
timeLog(label = 'default', ...data) {
417-
// Coerces everything other than Symbol to a string
418-
label = `${label}`;
419-
timeLogImpl(this, 'timeLog', label, data);
420-
trace(kTraceInstant, kTraceConsoleCategory, `time::${label}`, 0);
406+
if (this[kInternalTimeLogImpl] === undefined)
407+
this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
408+
409+
timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data);
421410
},
422411

423412
trace: function trace(...args) {
@@ -611,63 +600,6 @@ const consoleMethods = {
611600
},
612601
};
613602

614-
// Returns true if label was found
615-
function timeLogImpl(self, name, label, data) {
616-
const time = self._times.get(label);
617-
if (time === undefined) {
618-
process.emitWarning(`No such label '${label}' for console.${name}()`);
619-
return false;
620-
}
621-
const duration = process.hrtime(time);
622-
const ms = duration[0] * 1000 + duration[1] / 1e6;
623-
624-
const formatted = formatTime(ms);
625-
626-
if (data === undefined) {
627-
self.log('%s: %s', label, formatted);
628-
} else {
629-
self.log('%s: %s', label, formatted, ...new SafeArrayIterator(data));
630-
}
631-
return true;
632-
}
633-
634-
function pad(value) {
635-
return StringPrototypePadStart(`${value}`, 2, '0');
636-
}
637-
638-
function formatTime(ms) {
639-
let hours = 0;
640-
let minutes = 0;
641-
let seconds = 0;
642-
643-
if (ms >= kSecond) {
644-
if (ms >= kMinute) {
645-
if (ms >= kHour) {
646-
hours = MathFloor(ms / kHour);
647-
ms = ms % kHour;
648-
}
649-
minutes = MathFloor(ms / kMinute);
650-
ms = ms % kMinute;
651-
}
652-
seconds = ms / kSecond;
653-
}
654-
655-
if (hours !== 0 || minutes !== 0) {
656-
({ 0: seconds, 1: ms } = StringPrototypeSplit(
657-
NumberPrototypeToFixed(seconds, 3),
658-
'.',
659-
));
660-
const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes;
661-
return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`;
662-
}
663-
664-
if (seconds !== 0) {
665-
return `${NumberPrototypeToFixed(seconds, 3)}s`;
666-
}
667-
668-
return `${Number(NumberPrototypeToFixed(ms, 3))}ms`;
669-
}
670-
671603
const keyKey = 'Key';
672604
const valuesKey = 'Values';
673605
const indexKey = '(index)';
@@ -722,5 +654,4 @@ module.exports = {
722654
kBindStreamsLazy,
723655
kBindProperties,
724656
initializeGlobalConsole,
725-
formatTime, // exported for tests
726657
};

‎lib/internal/main/repl.js

+1-2
Original file line numberDiff line numberDiff line change
@@ -24,8 +24,7 @@ markBootstrapComplete();
2424

2525
if (process.env.NODE_REPL_EXTERNAL_MODULE) {
2626
require('internal/modules/cjs/loader')
27-
.Module
28-
._load(process.env.NODE_REPL_EXTERNAL_MODULE, undefined, true);
27+
.wrapModuleLoad(process.env.NODE_REPL_EXTERNAL_MODULE, undefined, true);
2928
} else {
3029
// --input-type flag not supported in REPL
3130
if (getOptionValue('--input-type')) {

‎lib/internal/modules/cjs/loader.js

+30-4
Original file line numberDiff line numberDiff line change
@@ -108,6 +108,7 @@ module.exports = {
108108
initializeCJS,
109109
Module,
110110
wrapSafe,
111+
wrapModuleLoad,
111112
kIsMainSymbol,
112113
kIsCachedByESMLoader,
113114
kRequiredModuleSymbol,
@@ -189,6 +190,13 @@ const {
189190
isProxy,
190191
} = require('internal/util/types');
191192

193+
const { debuglog, debugWithTimer } = require('internal/util/debuglog');
194+
195+
let { startTimer, endTimer } = debugWithTimer('module_timer', (start, end) => {
196+
startTimer = start;
197+
endTimer = end;
198+
});
199+
192200
const isWindows = process.platform === 'win32';
193201

194202
const relativeResolveCache = { __proto__: null };
@@ -210,12 +218,30 @@ function internalRequire(module, id) {
210218
}
211219
requireDepth++;
212220
try {
213-
return Module._load(id, module, /* isMain */ false);
221+
return wrapModuleLoad(id, module, /* isMain */ false);
214222
} finally {
215223
requireDepth--;
216224
}
217225
}
218226

227+
/*
228+
* Internal method to add tracing capabilities for Module._load.
229+
*
230+
* See more {@link Module._load}
231+
*/
232+
function wrapModuleLoad(request, parent, isMain) {
233+
const logLabel = `[${parent?.id || ''}] [${request}]`;
234+
const traceLabel = `require('${request}')`;
235+
236+
startTimer(logLabel, traceLabel);
237+
238+
try {
239+
return Module._load(request, parent, isMain);
240+
} finally {
241+
endTimer(logLabel, traceLabel);
242+
}
243+
}
244+
219245
/**
220246
* Get a path's properties, using an in-memory cache to minimize lookups.
221247
* @param {string} filename Absolute path to the file
@@ -392,7 +418,7 @@ function setModuleParent(value) {
392418
this[kModuleParent] = value;
393419
}
394420

395-
let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
421+
let debug = debuglog('module', (fn) => {
396422
debug = fn;
397423
});
398424

@@ -1009,7 +1035,7 @@ function getExportsForCircularRequire(module) {
10091035
* 3. Otherwise, create a new module for the file and save it to the cache.
10101036
* Then have it load the file contents before returning its exports object.
10111037
* @param {string} request Specifier of module to load via `require`
1012-
* @param {string} parent Absolute path of the module importing the child
1038+
* @param {Module} parent Absolute path of the module importing the child
10131039
* @param {boolean} isMain Whether the module is the main entry point
10141040
*/
10151041
Module._load = function(request, parent, isMain) {
@@ -1307,7 +1333,7 @@ Module.prototype.require = function(id) {
13071333
}
13081334
requireDepth++;
13091335
try {
1310-
return Module._load(id, this, /* isMain */ false);
1336+
return wrapModuleLoad(id, this, /* isMain */ false);
13111337
} finally {
13121338
requireDepth--;
13131339
}

‎lib/internal/modules/esm/translators.js

+4-3
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,7 @@ const {
4343
const {
4444
kIsCachedByESMLoader,
4545
Module: CJSModule,
46+
wrapModuleLoad,
4647
kModuleSource,
4748
kModuleExport,
4849
kModuleExportNames,
@@ -197,7 +198,7 @@ function loadCJSModule(module, source, url, filename, isMain) {
197198
importAttributes = { __proto__: null, type: 'json' };
198199
break;
199200
case '.node':
200-
return CJSModule._load(specifier, module);
201+
return wrapModuleLoad(specifier, module);
201202
default:
202203
// fall through
203204
}
@@ -289,7 +290,7 @@ translators.set('commonjs-sync', function requireCommonJS(url, source, isMain) {
289290
return createCJSModuleWrap(url, source, isMain, (module, source, url, filename, isMain) => {
290291
assert(module === CJSModule._cache[filename]);
291292
assert(!isMain);
292-
CJSModule._load(filename, null, isMain);
293+
wrapModuleLoad(filename, null, isMain);
293294
});
294295
});
295296

@@ -314,7 +315,7 @@ translators.set('commonjs', async function commonjsStrategy(url, source,
314315
// obtained by calling the monkey-patchable CJS loader.
315316
const cjsLoader = source == null ? (module, source, url, filename, isMain) => {
316317
assert(module === CJSModule._cache[filename]);
317-
CJSModule._load(filename, undefined, isMain);
318+
wrapModuleLoad(filename, undefined, isMain);
318319
} : loadCJSModule;
319320

320321
try {

‎lib/internal/modules/run_main.js

+2-2
Original file line numberDiff line numberDiff line change
@@ -167,8 +167,8 @@ function executeUserEntryPoint(main = process.argv[1]) {
167167
// try to run the entry point via the CommonJS loader; and if that fails under certain conditions, retry as ESM.
168168
if (!useESMLoader) {
169169
const cjsLoader = require('internal/modules/cjs/loader');
170-
const { Module } = cjsLoader;
171-
Module._load(main, null, true);
170+
const { wrapModuleLoad } = cjsLoader;
171+
wrapModuleLoad(main, null, true);
172172
} else {
173173
const mainPath = resolvedMain || main;
174174
if (mainURL === undefined) {

0 commit comments

Comments
 (0)