FazBrowse GitHub Viewer | Trending |
URL:
| Home
Tools: [Download Repo ZIP]   [Original HTTPS Page]

module: print amount of load time of a cjs module · nodejs/node@b5c30e2 · GitHub

/ node Public

Commit b5c30e2

Browse files
H4ad
authored and
targos
committed
module: print amount of load time of a cjs module
PR-URL: #52213 Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
1 parent 812f0e9 commit b5c30e2

25 files changed

Lines changed: 573 additions & 112 deletions

‎lib/internal/console/constructor.js‎

Lines changed: 19 additions & 88 deletions
Original file line numberDiff line numberDiff line change
@@ -13,9 +13,6 @@ const {
1313
Boolean,
1414
ErrorCaptureStackTrace,
1515
FunctionPrototypeBind,
16-
MathFloor,
17-
Number,
18-
NumberPrototypeToFixed,
1916
ObjectDefineProperties,
2017
ObjectDefineProperty,
2118
ObjectKeys,
@@ -30,10 +27,8 @@ const {
3027
SafeSet,
3128
SafeWeakMap,
3229
StringPrototypeIncludes,
33-
StringPrototypePadStart,
3430
StringPrototypeRepeat,
3531
StringPrototypeSlice,
36-
StringPrototypeSplit,
3732
Symbol,
3833
SymbolHasInstance,
3934
SymbolToStringTag,
@@ -63,19 +58,14 @@ const {
6358
isTypedArray, isSet, isMap, isSetIterator, isMapIterator,
6459
} = require('internal/util/types');
6560
const {
66-
CHAR_LOWERCASE_B: kTraceBegin,
67-
CHAR_LOWERCASE_E: kTraceEnd,
68-
CHAR_LOWERCASE_N: kTraceInstant,
6961
CHAR_UPPERCASE_C: kTraceCount,
7062
} = require('internal/constants');
7163
const { styleText } = require('util');
7264
const kCounts = Symbol('counts');
65+
const { time, timeLog, timeEnd, kNone } = require('internal/util/debuglog');
7366

7467
const kTraceConsoleCategory = 'node,node.console';
7568

76-
const kSecond = 1000;
77-
const kMinute = 60 * kSecond;
78-
const kHour = 60 * kMinute;
7969
const kMaxGroupIndentation = 1000;
8070

8171
// Lazy loaded for startup performance.
@@ -101,6 +91,7 @@ const kBindStreamsEager = Symbol('kBindStreamsEager');
10191
const kBindStreamsLazy = Symbol('kBindStreamsLazy');
10292
const kUseStdout = Symbol('kUseStdout');
10393
const kUseStderr = Symbol('kUseStderr');
94+
const kInternalTimeLogImpl = Symbol('kInternalTimeLogImpl');
10495

10596
const optionsMap = new SafeWeakMap();
10697
function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
@@ -381,6 +372,14 @@ function createWriteErrorHandler(instance, streamSymbol) {
381372
};
382373
}
383374

375+
function timeLogImpl(label, formatted, args) {
376+
if (args === undefined) {
377+
this.log('%s: %s', label, formatted);
378+
} else {
379+
this.log('%s: %s', label, formatted, ...new SafeArrayIterator(args));
380+
}
381+
}
382+
384383
const consoleMethods = {
385384
log(...args) {
386385
this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args));
@@ -404,31 +403,21 @@ const consoleMethods = {
404403
},
405404

406405
time(label = 'default') {
407-
// Coerces everything other than Symbol to a string
408-
label = `${label}`;
409-
if (this._times.has(label)) {
410-
process.emitWarning(`Label '${label}' already exists for console.time()`);
411-
return;
412-
}
413-
trace(kTraceBegin, kTraceConsoleCategory, `time::${label}`, 0);
414-
this._times.set(label, process.hrtime());
406+
time(this._times, kTraceConsoleCategory, 'console.time()', kNone, label, `time::${label}`);
415407
},
416408

417409
timeEnd(label = 'default') {
418-
// Coerces everything other than Symbol to a string
419-
label = `${label}`;
420-
const found = timeLogImpl(this, 'timeEnd', label);
421-
trace(kTraceEnd, kTraceConsoleCategory, `time::${label}`, 0);
422-
if (found) {
423-
this._times.delete(label);
424-
}
410+
if (this[kInternalTimeLogImpl] === undefined)
411+
this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
412+
413+
timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`);
425414
},
426415

427416
timeLog(label = 'default', ...data) {
428-
// Coerces everything other than Symbol to a string
429-
label = `${label}`;
430-
timeLogImpl(this, 'timeLog', label, data);
431-
trace(kTraceInstant, kTraceConsoleCategory, `time::${label}`, 0);
417+
if (this[kInternalTimeLogImpl] === undefined)
418+
this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this);
419+
420+
timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data);
432421
},
433422

434423
trace: function trace(...args) {
@@ -627,63 +616,6 @@ const consoleMethods = {
627616
},
628617
};
629618

630-
// Returns true if label was found
631-
function timeLogImpl(self, name, label, data) {
632-
const time = self._times.get(label);
633-
if (time === undefined) {
634-
process.emitWarning(`No such label '${label}' for console.${name}()`);
635-
return false;
636-
}
637-
const duration = process.hrtime(time);
638-
const ms = duration[0] * 1000 + duration[1] / 1e6;
639-
640-
const formatted = formatTime(ms);
641-
642-
if (data === undefined) {
643-
self.log('%s: %s', label, formatted);
644-
} else {
645-
self.log('%s: %s', label, formatted, ...new SafeArrayIterator(data));
646-
}
647-
return true;
648-
}
649-
650-
function pad(value) {
651-
return StringPrototypePadStart(`${value}`, 2, '0');
652-
}
653-
654-
function formatTime(ms) {
655-
let hours = 0;
656-
let minutes = 0;
657-
let seconds = 0;
658-
659-
if (ms >= kSecond) {
660-
if (ms >= kMinute) {
661-
if (ms >= kHour) {
662-
hours = MathFloor(ms / kHour);
663-
ms = ms % kHour;
664-
}
665-
minutes = MathFloor(ms / kMinute);
666-
ms = ms % kMinute;
667-
}
668-
seconds = ms / kSecond;
669-
}
670-
671-
if (hours !== 0 || minutes !== 0) {
672-
({ 0: seconds, 1: ms } = StringPrototypeSplit(
673-
NumberPrototypeToFixed(seconds, 3),
674-
'.',
675-
));
676-
const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes;
677-
return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`;
678-
}
679-
680-
if (seconds !== 0) {
681-
return `${NumberPrototypeToFixed(seconds, 3)}s`;
682-
}
683-
684-
return `${Number(NumberPrototypeToFixed(ms, 3))}ms`;
685-
}
686-
687619
const keyKey = 'Key';
688620
const valuesKey = 'Values';
689621
const indexKey = '(index)';
@@ -743,5 +675,4 @@ module.exports = {
743675
kBindStreamsLazy,
744676
kBindProperties,
745677
initializeGlobalConsole,
746-
formatTime, // exported for tests
747678
};

‎lib/internal/main/repl.js‎

Lines changed: 1 addition & 2 deletions
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‎

Lines changed: 29 additions & 3 deletions
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,
@@ -181,6 +182,13 @@ const {
181182
isProxy,
182183
} = require('internal/util/types');
183184

185+
const { debuglog, debugWithTimer } = require('internal/util/debuglog');
186+
187+
let { startTimer, endTimer } = debugWithTimer('module_timer', (start, end) => {
188+
startTimer = start;
189+
endTimer = end;
190+
});
191+
184192
const isWindows = process.platform === 'win32';
185193

186194
const relativeResolveCache = { __proto__: null };
@@ -189,6 +197,24 @@ let requireDepth = 0;
189197
let isPreloading = false;
190198
let statCache = null;
191199

200+
/**
201+
* Internal method to add tracing capabilities for Module._load.
202+
*
203+
* See more {@link Module._load}
204+
*/
205+
function wrapModuleLoad(request, parent, isMain) {
206+
const logLabel = `[${parent?.id || ''}] [${request}]`;
207+
const traceLabel = `require('${request}')`;
208+
209+
startTimer(logLabel, traceLabel);
210+
211+
try {
212+
return Module._load(request, parent, isMain);
213+
} finally {
214+
endTimer(logLabel, traceLabel);
215+
}
216+
}
217+
192218
/**
193219
* Get a path's properties, using an in-memory cache to minimize lookups.
194220
* @param {string} filename Absolute path to the file
@@ -354,7 +380,7 @@ function setModuleParent(value) {
354380
this[kModuleParent] = value;
355381
}
356382

357-
let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
383+
let debug = debuglog('module', (fn) => {
358384
debug = fn;
359385
});
360386

@@ -971,7 +997,7 @@ function getExportsForCircularRequire(module) {
971997
* 3. Otherwise, create a new module for the file and save it to the cache.
972998
* Then have it load the file contents before returning its exports object.
973999
* @param {string} request Specifier of module to load via `require`
974-
* @param {string} parent Absolute path of the module importing the child
1000+
* @param {Module} parent Absolute path of the module importing the child
9751001
* @param {boolean} isMain Whether the module is the main entry point
9761002
*/
9771003
Module._load = function(request, parent, isMain) {
@@ -1268,7 +1294,7 @@ Module.prototype.require = function(id) {
12681294
}
12691295
requireDepth++;
12701296
try {
1271-
return Module._load(id, this, /* isMain */ false);
1297+
return wrapModuleLoad(id, this, /* isMain */ false);
12721298
} finally {
12731299
requireDepth--;
12741300
}

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

Lines changed: 4 additions & 3 deletions
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‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -154,8 +154,8 @@ function executeUserEntryPoint(main = process.argv[1]) {
154154
// try to run the entry point via the CommonJS loader; and if that fails under certain conditions, retry as ESM.
155155
if (!useESMLoader) {
156156
const cjsLoader = require('internal/modules/cjs/loader');
157-
const { Module } = cjsLoader;
158-
Module._load(main, null, true);
157+
const { wrapModuleLoad } = cjsLoader;
158+
wrapModuleLoad(main, null, true);
159159
} else {
160160
const mainPath = resolvedMain || main;
161161
if (mainURL === undefined) {

0 commit comments

Comments
 (0)
Back | FazBrowse Home | New Git URL