Skip to content

Commit

Permalink
module: print amount of load time of a cjs module
Browse files Browse the repository at this point in the history 
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>
  • Loading branch information
@H4ad
H4ad committed May 30, 2024
1 parent 47c5571 commit f883865
Show file tree
Hide file tree
Showing 25 changed files with 573 additions and 112 deletions.
107 changes: 19 additions & 88 deletions lib/internal/console/constructor.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,6 @@ const {
Boolean,
ErrorCaptureStackTrace,
FunctionPrototypeBind,
MathFloor,
Number,
NumberPrototypeToFixed,
ObjectDefineProperties,
ObjectDefineProperty,
ObjectKeys,
Expand All @@ -30,10 +27,8 @@ const {
SafeSet,
SafeWeakMap,
StringPrototypeIncludes,
StringPrototypePadStart,
StringPrototypeRepeat,
StringPrototypeSlice,
StringPrototypeSplit,
Symbol,
SymbolHasInstance,
SymbolToStringTag,
Expand Down Expand Up @@ -63,19 +58,14 @@ 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 { styleText } = require('util');
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.
Expand All @@ -101,6 +91,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 */) {
Expand Down Expand Up @@ -381,6 +372,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));
Expand All @@ -404,31 +403,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) {
Expand Down Expand Up @@ -627,63 +616,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)';
Expand Down Expand Up @@ -743,5 +675,4 @@ module.exports = {
kBindStreamsLazy,
kBindProperties,
initializeGlobalConsole,
formatTime, // exported for tests
};
3 changes: 1 addition & 2 deletions lib/internal/main/repl.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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')) {
Expand Down
32 changes: 29 additions & 3 deletions lib/internal/modules/cjs/loader.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -108,6 +108,7 @@ module.exports = {
initializeCJS,
Module,
wrapSafe,
wrapModuleLoad,
kIsMainSymbol,
kIsCachedByESMLoader,
kRequiredModuleSymbol,
Expand Down Expand Up @@ -181,6 +182,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 };
Expand All @@ -189,6 +197,24 @@ let requireDepth = 0;
let isPreloading = false;
let statCache = null;

/**
* 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
Expand Down Expand Up @@ -354,7 +380,7 @@ function setModuleParent(value) {
this[kModuleParent] = value;
}

let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
let debug = debuglog('module', (fn) => {
debug = fn;
});

Expand Down Expand Up @@ -971,7 +997,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) {
Expand Down Expand Up @@ -1268,7 +1294,7 @@ Module.prototype.require = function(id) {
}
requireDepth++;
try {
return Module._load(id, this, /* isMain */ false);
return wrapModuleLoad(id, this, /* isMain */ false);
} finally {
requireDepth--;
}
Expand Down
7 changes: 4 additions & 3 deletions lib/internal/modules/esm/translators.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,7 @@ const {
const {
kIsCachedByESMLoader,
Module: CJSModule,
wrapModuleLoad,
kModuleSource,
kModuleExport,
kModuleExportNames,
Expand Down Expand Up @@ -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
}
Expand Down Expand Up @@ -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);
});
});

Expand All @@ -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 {
Expand Down
4 changes: 2 additions & 2 deletions lib/internal/modules/run_main.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -154,8 +154,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) {
Expand Down
Loading

0 comments on commit f883865

Please sign in to comment.