From 79f1583231ab8acc4910f880c17240f7d27aa643 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 9 Apr 2024 21:48:58 -0300 Subject: [PATCH 01/29] module: print amount of load time of a cjs module --- lib/internal/modules/cjs/loader.js | 45 ++++++++++++++++++++-- lib/internal/util/debuglog.js | 5 +++ test/parallel/test-module-print-timing.mjs | 24 ++++++++++++ 3 files changed, 70 insertions(+), 4 deletions(-) create mode 100644 test/parallel/test-module-print-timing.mjs diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 69041d154c6fa2..739e5fd9553e22 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -60,6 +60,7 @@ const { StringPrototypeSplit, StringPrototypeStartsWith, Symbol, + Number, } = primordials; const { privateSymbols: { @@ -354,10 +355,22 @@ function setModuleParent(value) { this[kModuleParent] = 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('timing_module_cjs') ? process.hrtime.bigint : () => 0; + + return hrtimeBigIntTimingFn(); +}; + +let debugTiming = debuglog('timing_module_cjs', (fn) => { + debugTiming = fn; +}); + ObjectDefineProperty(Module.prototype, 'parent', { __proto__: null, get: pendingDeprecate( @@ -963,6 +976,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. @@ -971,10 +988,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); @@ -989,8 +1008,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]; @@ -1006,6 +1031,8 @@ Module._load = function(request, parent, isMain) { } const module = loadBuiltinModule(id, request); + + logTiming(request, parent, start); return module.exports; } @@ -1020,7 +1047,11 @@ Module._load = function(request, parent, isMain) { // comes from required CJS, and we can consider it a circular // dependency when it's cached. if (!cachedModule[kIsCachedByESMLoader]) { - return getExportsForCircularRequire(cachedModule); + const result = getExportsForCircularRequire(cachedModule); + + logTiming(request, parent, start); + + return result; } // If it's cached by the ESM loader as a way to indirectly pass // the module in to avoid creating it twice, the loading request @@ -1030,11 +1061,15 @@ Module._load = function(request, parent, isMain) { return getExportsForCircularRequire(cachedModule); } // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. + logTiming(request, parent, start); cachedModule[kModuleCircularVisited] = true; } if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { const mod = loadBuiltinModule(filename, request); + + logTiming(request, parent, start); + return mod.exports; } @@ -1085,6 +1120,8 @@ Module._load = function(request, parent, isMain) { } } + logTiming(request, parent, start); + return module.exports; }; diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 854441216e67e5..a5fa1d8ec81ab2 100644 --- a/lib/internal/util/debuglog.js +++ b/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, }; diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs new file mode 100644 index 00000000000000..1b7a27323a81ed --- /dev/null +++ b/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 = 'timing_module_cjs'; + const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], { + env: { + NODE_DEBUG: 'timing_module_cjs', + }, + }); + + 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('TIMING_MODULE_CJS'), `Not found TIMING_MODULE_CJS on ${firstLine}`); + assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); + assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); +}); From 11ea88a5245b91a4abee14ee115692fadf73252f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 21:00:14 -0300 Subject: [PATCH 02/29] try support both node_debug and trace by introducing a new module --- lib/internal/console/constructor.js | 127 +++------------ lib/internal/modules/cjs/loader.js | 36 ++--- lib/internal/util/debuglog.js | 178 ++++++++++++++++++++- lib/internal/util/trace_timer.js | 155 ++++++++++++++++++ test/parallel/test-bootstrap-modules.js | 1 + test/parallel/test-console-formatTime.js | 2 +- test/parallel/test-module-print-timing.mjs | 5 +- 7 files changed, 372 insertions(+), 132 deletions(-) create mode 100644 lib/internal/util/trace_timer.js diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 913b80e6eb567c..9b3e618094b8e3 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -13,9 +13,6 @@ const { Boolean, ErrorCaptureStackTrace, FunctionPrototypeBind, - MathFloor, - Number, - NumberPrototypeToFixed, ObjectDefineProperties, ObjectDefineProperty, ObjectKeys, @@ -30,10 +27,8 @@ const { SafeSet, SafeWeakMap, StringPrototypeIncludes, - StringPrototypePadStart, StringPrototypeRepeat, StringPrototypeSlice, - StringPrototypeSplit, Symbol, SymbolHasInstance, SymbolToStringTag, @@ -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, timeEnd, timeLog } = require('internal/util/trace_timer'); const kTraceConsoleCategory = 'node,node.console'; -const kSecond = 1000; -const kMinute = 60 * kSecond; -const kHour = 60 * kMinute; const kMaxGroupIndentation = 1000; // Lazy loaded for startup performance. @@ -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 */) { @@ -147,7 +138,7 @@ function Console(options /* or: stdout, stderr, ignoreErrors = true */) { validateObject(inspectOptions, 'options.inspectOptions'); if (inspectOptions.colors !== undefined && - options.colorMode !== undefined) { + options.colorMode !== undefined) { throw new ERR_INCOMPATIBLE_OPTION_PAIR( 'options.inspectOptions.color', 'colorMode'); } @@ -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)); @@ -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()', 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()', this[kInternalTimeLogImpl], 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()', this[kInternalTimeLogImpl], label, data); }, trace: function trace(...args) { @@ -525,9 +514,9 @@ const consoleMethods = { const _inspect = (v) => { const depth = v !== null && - typeof v === 'object' && - !isArray(v) && - ObjectKeys(v).length > 2 ? -1 : 0; + typeof v === 'object' && + !isArray(v) && + ObjectKeys(v).length > 2 ? -1 : 0; const opt = { depth, maxArrayLength: 3, @@ -597,7 +586,7 @@ const consoleMethods = { for (; i < indexKeyArray.length; i++) { const item = tabularData[indexKeyArray[i]]; const primitive = item === null || - (typeof item !== 'function' && typeof item !== 'object'); + (typeof item !== 'function' && typeof item !== 'object'); if (properties === undefined && primitive) { hasPrimitives = true; valuesKeyArray[i] = _inspect(item); @@ -606,7 +595,7 @@ const consoleMethods = { for (const key of keys) { map[key] ??= []; if ((primitive && properties) || - !ObjectPrototypeHasOwnProperty(item, key)) + !ObjectPrototypeHasOwnProperty(item, key)) map[key][i] = ''; else map[key][i] = _inspect(item[key]); @@ -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)'; @@ -691,13 +623,7 @@ const iterKey = '(iteration index)'; const isArray = (v) => ArrayIsArray(v) || isTypedArray(v) || isBuffer(v); -// TODO: remove string type check once the styleText supports objects -// Return true if all args are type string -const shouldColorize = (args) => { - return lazyUtilColors().hasColors && !ArrayPrototypeSome(args, (arg) => typeof arg !== 'string'); -}; - -function noop() {} +function noop() { } for (const method of ReflectOwnKeys(consoleMethods)) Console.prototype[method] = consoleMethods[method]; @@ -743,5 +669,4 @@ module.exports = { kBindStreamsLazy, kBindProperties, initializeGlobalConsole, - formatTime, // exported for tests }; diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 739e5fd9553e22..d595784afef7e4 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -60,7 +60,6 @@ const { StringPrototypeSplit, StringPrototypeStartsWith, Symbol, - Number, } = primordials; const { privateSymbols: { @@ -355,20 +354,15 @@ function setModuleParent(value) { this[kModuleParent] = value; } -const { debuglog, isDebugEnabled } = require('internal/util/debuglog'); +const { debuglog, debugWithTimer } = require('internal/util/debuglog'); let debug = debuglog('module', (fn) => { debug = fn; }); -let hrtimeBigIntTimingFn = () => { - hrtimeBigIntTimingFn = isDebugEnabled('timing_module_cjs') ? process.hrtime.bigint : () => 0; - - return hrtimeBigIntTimingFn(); -}; - -let debugTiming = debuglog('timing_module_cjs', (fn) => { - debugTiming = fn; +let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => { + startTimer = start; + endTimer = end; }); ObjectDefineProperty(Module.prototype, 'parent', { @@ -976,10 +970,6 @@ 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. @@ -992,7 +982,9 @@ function logTiming(request, parent, start) { * @param {boolean} isMain Whether the module is the main entry point */ Module._load = function(request, parent, isMain) { - const start = hrtimeBigIntTimingFn(); + const label = `[${parent?.id || ''}] [${request}]`; + + startTimer(label); let relResolveCacheIdentifier; if (parent) { @@ -1010,12 +1002,12 @@ Module._load = function(request, parent, isMain) { if (!cachedModule.loaded) { const result = getExportsForCircularRequire(cachedModule); - logTiming(request, parent, start); + endTimer(label); return result; } - logTiming(request, parent, start); + endTimer(label); return cachedModule.exports; } delete relativeResolveCache[relResolveCacheIdentifier]; @@ -1032,7 +1024,7 @@ Module._load = function(request, parent, isMain) { const module = loadBuiltinModule(id, request); - logTiming(request, parent, start); + endTimer(label); return module.exports; } @@ -1049,7 +1041,7 @@ Module._load = function(request, parent, isMain) { if (!cachedModule[kIsCachedByESMLoader]) { const result = getExportsForCircularRequire(cachedModule); - logTiming(request, parent, start); + endTimer(label); return result; } @@ -1061,14 +1053,14 @@ Module._load = function(request, parent, isMain) { return getExportsForCircularRequire(cachedModule); } // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. - logTiming(request, parent, start); + endTimer(label); cachedModule[kModuleCircularVisited] = true; } if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { const mod = loadBuiltinModule(filename, request); - logTiming(request, parent, start); + endTimer(label); return mod.exports; } @@ -1120,7 +1112,7 @@ Module._load = function(request, parent, isMain) { } } - logTiming(request, parent, start); + endTimer(label); return module.exports; }; diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index a5fa1d8ec81ab2..912cfc1da01006 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -5,11 +5,14 @@ const { RegExp, RegExpPrototypeExec, SafeArrayIterator, + SafeMap, StringPrototypeToLowerCase, StringPrototypeToUpperCase, } = primordials; const { inspect, format, formatWithOptions } = require('internal/util/inspect'); +const { time, timeLog, timeEnd } = require('internal/util/trace_timer'); +const { isTraceCategoryEnabled } = internalBinding('trace_events'); // `debugImpls` and `testEnabled` are deliberately not initialized so any call // to `debuglog()` before `initializeDebugEnv()` is called will throw. @@ -43,7 +46,7 @@ function emitWarningIfNeeded(set) { } } -const noop = () => {}; +const noop = () => { }; let utilColors; function lazyUtilColors() { @@ -51,7 +54,14 @@ function lazyUtilColors() { return utilColors; } -function debuglogImpl(enabled, set) { +/** + * @typedef {(enabled: boolean, set: string) => any} DebugLogImplementation + */ + +/** + * @type {DebugLogImplementation} + */ +function debuglogImpl(enabled, set, args) { if (debugImpls[set] === undefined) { if (enabled) { const pid = process.pid; @@ -69,10 +79,23 @@ function debuglogImpl(enabled, set) { return debugImpls[set]; } +/** + * @typedef {(fn: DebugLogFn) => void} DebugLogCallback + */ + +/** + * @typedef {(message: string, ...args: any[]) => void} DebugLogFn + */ + // debuglogImpl depends on process.pid and process.env.NODE_DEBUG, // so it needs to be called lazily in top scopes of internal modules // that may be loaded before these run time states are allowed to // be accessed. +/** + * @param {string} set + * @param {DebugLogCallback} cb + * @returns {DebugLogFn} + */ function debuglog(set, cb) { function init() { set = StringPrototypeToUpperCase(set); @@ -115,12 +138,157 @@ function debuglog(set, cb) { return logger; } -function isDebugEnabled(set) { - return testEnabled(set); +function buildCategory(set) { + return `node,node.debuglog_${set}`; +} + +/** + * @type {Record} + */ +let tracesStores; + +/** + * @typedef {(label: string) => void} TimerStart + */ + +/** + * @typedef {(label: string) => void} TimerEnd + */ + +/** + * @typedef {(label: string, args?: any[]) => void} TimerLog + */ + +/** + * Debuglog with time fns and support for trace + * @param {string} set + * @param {(startTimer: TimerStart, endTimer: TimerEnd, logTimer: TimerLog) => void} cb + * @returns {{startTimer: TimerStart, endTimer: TimerEnd, logTimer: TimerLog}} + */ +function debugWithTimer(set, cb) { + set = StringPrototypeToUpperCase(set); + + if (tracesStores === undefined) { + tracesStores = { __proto__: null }; + } + + /** + * @type {import('internal/util/trace_timer').LogImpl} + */ + function logImpl(label, timeFormatted, args) { + const pid = process.pid; + const colors = { colors: lazyUtilColors().shouldColorize(process.stderr) }; + const coloredPID = inspect(pid, colors); + + if (args === undefined) + process.stderr.write(format('%s %s %s: %s\n', set, coloredPID, label, timeFormatted)); + else + process.stderr.write( + format( + '%s %s %s: %s\n', + set, + coloredPID, + label, + timeFormatted, + ...new SafeArrayIterator(args), + ), + ); + } + + const kTraceCategory = buildCategory(StringPrototypeToLowerCase(set)); + /** + * @type {import('internal/util/trace_timer').LogImpl} + */ + let selectedLogImpl; + let categoryEnabled = false; + + /** + * @type {TimerStart} + */ + function internalStartTimer(label) { + if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { + return; + } + + time(tracesStores[set], kTraceCategory, 'debuglog.time', label); + } + + /** + * @type {TimerEnd} + */ + function internalEndTimer(label) { + if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { + return; + } + + timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, label); + } + + /** + * @type {TimerLog} + */ + function internalLogTimer(label, args) { + if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { + return; + } + + timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, label, args); + } + + function init() { + if (tracesStores[set] === undefined) { + tracesStores[set] = new SafeMap(); + } + emitWarningIfNeeded(set); + categoryEnabled = testEnabled(set); + selectedLogImpl = categoryEnabled ? logImpl : noop; + } + + /** + * @type {TimerStart} + */ + const startTimer = (label) => { + init(); + + if (cb) + cb(internalStartTimer, internalEndTimer, internalLogTimer); + + return internalStartTimer(label); + }; + + /** + * @type {TimerEnd} + */ + const endTimer = (label) => { + init(); + + if (cb) + cb(internalStartTimer, internalEndTimer, internalLogTimer); + + return internalEndTimer(label); + }; + + /** + * @type {TimerLog} + */ + const logTimer = (label, args) => { + init(); + + if (cb) + cb(internalStartTimer, internalEndTimer, internalLogTimer); + + return internalLogTimer(label, args); + }; + + return { + startTimer, + endTimer, + logTimer, + }; } module.exports = { debuglog, - isDebugEnabled, + debugWithTimer, initializeDebugEnv, }; diff --git a/lib/internal/util/trace_timer.js b/lib/internal/util/trace_timer.js new file mode 100644 index 00000000000000..647137727e1a4c --- /dev/null +++ b/lib/internal/util/trace_timer.js @@ -0,0 +1,155 @@ +'use strict'; + +const { + MathFloor, + NumberPrototypeToFixed, + Number, + StringPrototypeSplit, + StringPrototypePadStart, +} = primordials; + +const { trace } = internalBinding('trace_events'); + +const { + CHAR_LOWERCASE_B: kTraceBegin, + CHAR_LOWERCASE_E: kTraceEnd, + CHAR_LOWERCASE_N: kTraceInstant, +} = require('internal/constants'); + +function pad(value) { + return StringPrototypePadStart(`${value}`, 2, '0'); +} + +const kSecond = 1000; +const kMinute = 60 * kSecond; +const kHour = 60 * kMinute; + +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`; +} + +/** + * @typedef {(label: string, timeFormatted: string, args?: any[]) => void} LogImpl + */ + +/** + * Returns true if label was found + * @param {string} timesStore + * @param {string} implementation + * @param {LogImpl} logImp + * @param {string} label + * @param {any} args + * @returns {boolean} + */ +function timeLogImpl(timesStore, implementation, logImp, label, args) { + const time = timesStore.get(label); + if (time === undefined) { + process.emitWarning(`No such label '${label}' for ${implementation}`); + return false; + } + + const duration = process.hrtime(time); + const ms = duration[0] * 1000 + duration[1] / 1e6; + + const formatted = formatTime(ms); + + if (args === undefined) { + logImp(label, formatted); + } else { + logImp(label, formatted, args); + } + + return true; +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {string} label + * @returns {void} + */ +function time(timesStore, traceCategory, implementation, label = 'default') { + // Coerces everything other than Symbol to a string + label = `${label}`; + if (timesStore.has(label)) { + process.emitWarning(`Label '${label}' already exists for ${implementation}`); + return; + } + + trace(kTraceBegin, traceCategory, `time::${label}`, 0); + timesStore.set(label, process.hrtime()); +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {LogImpl} logImpl + * @param {string} label + * @returns {void} + */ +function timeEnd(timesStore, traceCategory, implementation, logImpl, label = 'default') { + // Coerces everything other than Symbol to a string + label = `${label}`; + + const found = timeLogImpl(timesStore, implementation, logImpl, label); + trace(kTraceEnd, traceCategory, `time::${label}`, 0); + + if (found) { + timesStore.delete(label); + } +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {LogImpl} logImpl + * @param {string} label + * @param {any[]} args + * @returns {void} + */ +function timeLog(timesStore, traceCategory, implementation, logImpl, label = 'default', args) { + // Coerces everything other than Symbol to a string + label = `${label}`; + timeLogImpl(timesStore, implementation, logImpl, label, args); + + trace(kTraceInstant, traceCategory, `time::${label}`, 0); +} + +module.exports = { + time, + timeLog, + timeEnd, + formatTime, +}; diff --git a/test/parallel/test-bootstrap-modules.js b/test/parallel/test-bootstrap-modules.js index 6327fbeb2e7e1b..651ed2458cdf90 100644 --- a/test/parallel/test-bootstrap-modules.js +++ b/test/parallel/test-bootstrap-modules.js @@ -44,6 +44,7 @@ expected.beforePreExec = new Set([ 'NativeModule internal/assert', 'NativeModule internal/util/inspect', 'NativeModule internal/util/debuglog', + 'NativeModule internal/util/trace_timer', 'NativeModule internal/timers', 'NativeModule events', 'Internal Binding buffer', diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js index 0420013c50e77c..0e337097a98de6 100644 --- a/test/parallel/test-console-formatTime.js +++ b/test/parallel/test-console-formatTime.js @@ -1,7 +1,7 @@ 'use strict'; // Flags: --expose-internals require('../common'); -const { formatTime } = require('internal/console/constructor'); +const { formatTime } = require('internal/util/trace_timer'); const assert = require('assert'); assert.strictEqual(formatTime(100.0096), '100.01ms'); diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 1b7a27323a81ed..b0f6b86a609607 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -4,10 +4,9 @@ import { execPath } from 'node:process'; import { it } from 'node:test'; it('should print the timing information for cjs', async () => { - process.env.NODE_DEBUG = 'timing_module_cjs'; const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], { env: { - NODE_DEBUG: 'timing_module_cjs', + NODE_DEBUG: 'module_cjs', }, }); @@ -18,7 +17,7 @@ it('should print the timing information for cjs', async () => { const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); assert.notStrictEqual(firstLine, undefined); - assert.ok(firstLine.includes('TIMING_MODULE_CJS'), `Not found TIMING_MODULE_CJS on ${firstLine}`); + assert.ok(firstLine.includes('MODULE_CJS'), `Not found MODULE_CJS on ${firstLine}`); assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); }); From facfd58bd8ad90396bfee6e5dccc6dc9de96987d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 30 Mar 2024 10:59:23 -0300 Subject: [PATCH 03/29] add trace label to better visualization --- lib/internal/console/constructor.js | 6 +-- lib/internal/modules/cjs/loader.js | 19 +++++----- lib/internal/util/debuglog.js | 30 +++++++-------- lib/internal/util/trace_timer.js | 58 ++++++++++++++++++++--------- 4 files changed, 68 insertions(+), 45 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 9b3e618094b8e3..fe88072cad91a0 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -403,21 +403,21 @@ const consoleMethods = { }, time(label = 'default') { - time(this._times, kTraceConsoleCategory, 'console.time()', label); + time(this._times, kTraceConsoleCategory, 'console.time()', label, `time::${label}`); }, timeEnd(label = 'default') { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label); + timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label, `time::${label}`); }, timeLog(label = 'default', ...data) { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, data); + timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, `time::${label}`, data); }, trace: function trace(...args) { diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index d595784afef7e4..404bcbff5fc11f 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -982,9 +982,10 @@ function getExportsForCircularRequire(module) { * @param {boolean} isMain Whether the module is the main entry point */ Module._load = function(request, parent, isMain) { - const label = `[${parent?.id || ''}] [${request}]`; + const logLabel = `[${parent?.id || ''}] [${request}]`; + const traceLabel = `require('${request}')`; - startTimer(label); + startTimer(logLabel, traceLabel); let relResolveCacheIdentifier; if (parent) { @@ -1002,12 +1003,12 @@ Module._load = function(request, parent, isMain) { if (!cachedModule.loaded) { const result = getExportsForCircularRequire(cachedModule); - endTimer(label); + endTimer(logLabel, traceLabel); return result; } - endTimer(label); + endTimer(logLabel, traceLabel); return cachedModule.exports; } delete relativeResolveCache[relResolveCacheIdentifier]; @@ -1024,7 +1025,7 @@ Module._load = function(request, parent, isMain) { const module = loadBuiltinModule(id, request); - endTimer(label); + endTimer(logLabel, traceLabel); return module.exports; } @@ -1041,7 +1042,7 @@ Module._load = function(request, parent, isMain) { if (!cachedModule[kIsCachedByESMLoader]) { const result = getExportsForCircularRequire(cachedModule); - endTimer(label); + endTimer(logLabel, traceLabel); return result; } @@ -1053,14 +1054,14 @@ Module._load = function(request, parent, isMain) { return getExportsForCircularRequire(cachedModule); } // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. - endTimer(label); + endTimer(logLabel, traceLabel); cachedModule[kModuleCircularVisited] = true; } if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { const mod = loadBuiltinModule(filename, request); - endTimer(label); + endTimer(logLabel, traceLabel); return mod.exports; } @@ -1112,7 +1113,7 @@ Module._load = function(request, parent, isMain) { } } - endTimer(label); + endTimer(logLabel, traceLabel); return module.exports; }; diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 912cfc1da01006..9d467be0e42923 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -148,15 +148,15 @@ function buildCategory(set) { let tracesStores; /** - * @typedef {(label: string) => void} TimerStart + * @typedef {(logLabel: string, traceLabel?: string) => void} TimerStart */ /** - * @typedef {(label: string) => void} TimerEnd + * @typedef {(label: string, traceLabel?: string) => void} TimerEnd */ /** - * @typedef {(label: string, args?: any[]) => void} TimerLog + * @typedef {(label: string, traceLabel?: string, args?: any[]) => void} TimerLog */ /** @@ -205,34 +205,34 @@ function debugWithTimer(set, cb) { /** * @type {TimerStart} */ - function internalStartTimer(label) { + function internalStartTimer(logLabel, traceLabel) { if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { return; } - time(tracesStores[set], kTraceCategory, 'debuglog.time', label); + time(tracesStores[set], kTraceCategory, 'debuglog.time', logLabel, traceLabel); } /** * @type {TimerEnd} */ - function internalEndTimer(label) { + function internalEndTimer(logLabel, traceLabel) { if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { return; } - timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, label); + timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel); } /** * @type {TimerLog} */ - function internalLogTimer(label, args) { + function internalLogTimer(logLabel, traceLabel, args) { if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { return; } - timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, label, args); + timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args); } function init() { @@ -247,37 +247,37 @@ function debugWithTimer(set, cb) { /** * @type {TimerStart} */ - const startTimer = (label) => { + const startTimer = (logLabel, traceLabel) => { init(); if (cb) cb(internalStartTimer, internalEndTimer, internalLogTimer); - return internalStartTimer(label); + return internalStartTimer(logLabel, traceLabel); }; /** * @type {TimerEnd} */ - const endTimer = (label) => { + const endTimer = (logLabel, traceLabel) => { init(); if (cb) cb(internalStartTimer, internalEndTimer, internalLogTimer); - return internalEndTimer(label); + return internalEndTimer(logLabel, traceLabel); }; /** * @type {TimerLog} */ - const logTimer = (label, args) => { + const logTimer = (logLabel, traceLabel, args) => { init(); if (cb) cb(internalStartTimer, internalEndTimer, internalLogTimer); - return internalLogTimer(label, args); + return internalLogTimer(logLabel, traceLabel, args); }; return { diff --git a/lib/internal/util/trace_timer.js b/lib/internal/util/trace_timer.js index 647137727e1a4c..a821b2685d6f59 100644 --- a/lib/internal/util/trace_timer.js +++ b/lib/internal/util/trace_timer.js @@ -95,19 +95,26 @@ function timeLogImpl(timesStore, implementation, logImp, label, args) { * @param {SafeMap} timesStore * @param {string} traceCategory * @param {string} implementation - * @param {string} label + * @param {string} logLabel * @returns {void} */ -function time(timesStore, traceCategory, implementation, label = 'default') { +function time(timesStore, traceCategory, implementation, logLabel = 'default', traceLabel = undefined) { // Coerces everything other than Symbol to a string - label = `${label}`; - if (timesStore.has(label)) { - process.emitWarning(`Label '${label}' already exists for ${implementation}`); + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if (timesStore.has(logLabel)) { + process.emitWarning(`Label '${logLabel}' already exists for ${implementation}`); return; } - trace(kTraceBegin, traceCategory, `time::${label}`, 0); - timesStore.set(label, process.hrtime()); + trace(kTraceBegin, traceCategory, traceLabel, 0); + timesStore.set(logLabel, process.hrtime()); } /** @@ -115,18 +122,25 @@ function time(timesStore, traceCategory, implementation, label = 'default') { * @param {string} traceCategory * @param {string} implementation * @param {LogImpl} logImpl - * @param {string} label + * @param {string} logLabel + * @param {string} traceLabel * @returns {void} */ -function timeEnd(timesStore, traceCategory, implementation, logImpl, label = 'default') { +function timeEnd(timesStore, traceCategory, implementation, logImpl, logLabel = 'default', traceLabel = undefined) { // Coerces everything other than Symbol to a string - label = `${label}`; + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } - const found = timeLogImpl(timesStore, implementation, logImpl, label); - trace(kTraceEnd, traceCategory, `time::${label}`, 0); + const found = timeLogImpl(timesStore, implementation, logImpl, logLabel); + trace(kTraceEnd, traceCategory, traceLabel, 0); if (found) { - timesStore.delete(label); + timesStore.delete(logLabel); } } @@ -135,16 +149,24 @@ function timeEnd(timesStore, traceCategory, implementation, logImpl, label = 'de * @param {string} traceCategory * @param {string} implementation * @param {LogImpl} logImpl - * @param {string} label + * @param {string} logLabel + * @param {string} traceLabel * @param {any[]} args * @returns {void} */ -function timeLog(timesStore, traceCategory, implementation, logImpl, label = 'default', args) { +function timeLog(timesStore, traceCategory, implementation, logImpl, logLabel = 'default', traceLabel = undefined, args) { // Coerces everything other than Symbol to a string - label = `${label}`; - timeLogImpl(timesStore, implementation, logImpl, label, args); + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + timeLogImpl(timesStore, implementation, logImpl, logLabel, args); - trace(kTraceInstant, traceCategory, `time::${label}`, 0); + trace(kTraceInstant, traceCategory, traceLabel, 0); } module.exports = { From db6028359e3b719ebea28f7383047b9142ba6917 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 30 Mar 2024 11:09:36 -0300 Subject: [PATCH 04/29] fix lint issue with max line --- lib/internal/util/trace_timer.js | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/lib/internal/util/trace_timer.js b/lib/internal/util/trace_timer.js index a821b2685d6f59..06de48f9ebba61 100644 --- a/lib/internal/util/trace_timer.js +++ b/lib/internal/util/trace_timer.js @@ -154,7 +154,15 @@ function timeEnd(timesStore, traceCategory, implementation, logImpl, logLabel = * @param {any[]} args * @returns {void} */ -function timeLog(timesStore, traceCategory, implementation, logImpl, logLabel = 'default', traceLabel = undefined, args) { +function timeLog( + timesStore, + traceCategory, + implementation, + logImpl, + logLabel = 'default', + traceLabel = undefined, + args, +) { // Coerces everything other than Symbol to a string logLabel = `${logLabel}`; From fc16e3d252f92b11fbff4091d0a74ac18c29862b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 30 Mar 2024 11:53:02 -0300 Subject: [PATCH 05/29] lazy load trace_timer --- lib/internal/console/constructor.js | 20 ++++++++++++++++---- lib/internal/util/debuglog.js | 17 +++++++++++++---- test/parallel/test-bootstrap-modules.js | 1 - 3 files changed, 29 insertions(+), 9 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index fe88072cad91a0..71c0065aa4c542 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -62,10 +62,22 @@ const { } = require('internal/constants'); const { styleText } = require('util'); const kCounts = Symbol('counts'); -const { time, timeEnd, timeLog } = require('internal/util/trace_timer'); const kTraceConsoleCategory = 'node,node.console'; +let _traceTimer; +/** + * @returns {import('internal/util/trace_timer')} + */ +function lazyTraceTimer() { + if (_traceTimer) { + return _traceTimer; + } + + _traceTimer = require('internal/util/trace_timer'); + return _traceTimer; +} + const kMaxGroupIndentation = 1000; // Lazy loaded for startup performance. @@ -403,21 +415,21 @@ const consoleMethods = { }, time(label = 'default') { - time(this._times, kTraceConsoleCategory, 'console.time()', label, `time::${label}`); + lazyTraceTimer().time(this._times, kTraceConsoleCategory, 'console.time()', label, `time::${label}`); }, timeEnd(label = 'default') { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label, `time::${label}`); + lazyTraceTimer().timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label, `time::${label}`); }, timeLog(label = 'default', ...data) { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, `time::${label}`, data); + lazyTraceTimer().timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, `time::${label}`, data); }, trace: function trace(...args) { diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 9d467be0e42923..9412803f113775 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -11,9 +11,18 @@ const { } = primordials; const { inspect, format, formatWithOptions } = require('internal/util/inspect'); -const { time, timeLog, timeEnd } = require('internal/util/trace_timer'); const { isTraceCategoryEnabled } = internalBinding('trace_events'); +let _traceTimer; +function lazyTraceTimer() { + if (_traceTimer) { + return _traceTimer; + } + + _traceTimer = require('internal/util/trace_timer'); + return _traceTimer; +} + // `debugImpls` and `testEnabled` are deliberately not initialized so any call // to `debuglog()` before `initializeDebugEnv()` is called will throw. let debugImpls; @@ -210,7 +219,7 @@ function debugWithTimer(set, cb) { return; } - time(tracesStores[set], kTraceCategory, 'debuglog.time', logLabel, traceLabel); + lazyTraceTimer().time(tracesStores[set], kTraceCategory, 'debuglog.time', logLabel, traceLabel); } /** @@ -221,7 +230,7 @@ function debugWithTimer(set, cb) { return; } - timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel); + lazyTraceTimer().timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel); } /** @@ -232,7 +241,7 @@ function debugWithTimer(set, cb) { return; } - timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args); + lazyTraceTimer().timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args); } function init() { diff --git a/test/parallel/test-bootstrap-modules.js b/test/parallel/test-bootstrap-modules.js index 651ed2458cdf90..6327fbeb2e7e1b 100644 --- a/test/parallel/test-bootstrap-modules.js +++ b/test/parallel/test-bootstrap-modules.js @@ -44,7 +44,6 @@ expected.beforePreExec = new Set([ 'NativeModule internal/assert', 'NativeModule internal/util/inspect', 'NativeModule internal/util/debuglog', - 'NativeModule internal/util/trace_timer', 'NativeModule internal/timers', 'NativeModule events', 'Internal Binding buffer', From 6cfb6084130e8d5ae88b8d6a121001801b61be49 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 30 Mar 2024 11:54:34 -0300 Subject: [PATCH 06/29] fix lint issues introduce when lazy load --- lib/internal/util/debuglog.js | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 9412803f113775..018df5fdf84aed 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -230,7 +230,8 @@ function debugWithTimer(set, cb) { return; } - lazyTraceTimer().timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel); + lazyTraceTimer() + .timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel); } /** @@ -241,7 +242,8 @@ function debugWithTimer(set, cb) { return; } - lazyTraceTimer().timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args); + lazyTraceTimer() + .timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args); } function init() { From 966b7b919dca7260337d33c4a3c7335bf316d2ff Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 9 Apr 2024 21:42:29 -0300 Subject: [PATCH 07/29] cleanup and added more tests --- lib/internal/console/constructor.js | 23 +- lib/internal/util/debuglog.js | 327 ++++++++++++++++----- lib/internal/util/trace_timer.js | 185 ------------ test/parallel/test-console-formatTime.js | 2 +- test/parallel/test-module-print-timing.mjs | 68 +++++ 5 files changed, 339 insertions(+), 266 deletions(-) delete mode 100644 lib/internal/util/trace_timer.js diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 71c0065aa4c542..3c9a2aa8f1cda2 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -65,17 +65,17 @@ const kCounts = Symbol('counts'); const kTraceConsoleCategory = 'node,node.console'; -let _traceTimer; +let _debugLog; /** - * @returns {import('internal/util/trace_timer')} + * @returns {import('internal/util/debuglog')} */ -function lazyTraceTimer() { - if (_traceTimer) { - return _traceTimer; +function lazyDebugLog() { + if (_debugLog) { + return _debugLog; } - _traceTimer = require('internal/util/trace_timer'); - return _traceTimer; + _debugLog = require('internal/util/debuglog'); + return _debugLog; } const kMaxGroupIndentation = 1000; @@ -415,21 +415,24 @@ const consoleMethods = { }, time(label = 'default') { - lazyTraceTimer().time(this._times, kTraceConsoleCategory, 'console.time()', label, `time::${label}`); + lazyDebugLog() + .time(this._times, kTraceConsoleCategory, 'console.time()', lazyDebugLog().kNone, label, `time::${label}`); }, timeEnd(label = 'default') { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - lazyTraceTimer().timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label, `time::${label}`); + lazyDebugLog() + .timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', lazyDebugLog().kNone, this[kInternalTimeLogImpl], label, `time::${label}`); }, timeLog(label = 'default', ...data) { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - lazyTraceTimer().timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, `time::${label}`, data); + lazyDebugLog() + .timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', lazyDebugLog().kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data); }, trace: function trace(...args) { diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 018df5fdf84aed..2ad38bc5f27f53 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -1,6 +1,9 @@ 'use strict'; const { + Number, + NumberPrototypeToFixed, + MathFloor, ObjectDefineProperty, RegExp, RegExpPrototypeExec, @@ -8,20 +11,16 @@ const { SafeMap, StringPrototypeToLowerCase, StringPrototypeToUpperCase, + StringPrototypeSplit, + StringPrototypePadStart, } = primordials; - +const { + CHAR_LOWERCASE_B: kTraceBegin, + CHAR_LOWERCASE_E: kTraceEnd, + CHAR_LOWERCASE_N: kTraceInstant, +} = require('internal/constants'); const { inspect, format, formatWithOptions } = require('internal/util/inspect'); -const { isTraceCategoryEnabled } = internalBinding('trace_events'); - -let _traceTimer; -function lazyTraceTimer() { - if (_traceTimer) { - return _traceTimer; - } - - _traceTimer = require('internal/util/trace_timer'); - return _traceTimer; -} +const { isTraceCategoryEnabled, trace } = internalBinding('trace_events'); // `debugImpls` and `testEnabled` are deliberately not initialized so any call // to `debuglog()` before `initializeDebugEnv()` is called will throw. @@ -55,7 +54,7 @@ function emitWarningIfNeeded(set) { } } -const noop = () => { }; +const noop = () => {}; let utilColors; function lazyUtilColors() { @@ -63,13 +62,6 @@ function lazyUtilColors() { return utilColors; } -/** - * @typedef {(enabled: boolean, set: string) => any} DebugLogImplementation - */ - -/** - * @type {DebugLogImplementation} - */ function debuglogImpl(enabled, set, args) { if (debugImpls[set] === undefined) { if (enabled) { @@ -88,23 +80,10 @@ function debuglogImpl(enabled, set, args) { return debugImpls[set]; } -/** - * @typedef {(fn: DebugLogFn) => void} DebugLogCallback - */ - -/** - * @typedef {(message: string, ...args: any[]) => void} DebugLogFn - */ - // debuglogImpl depends on process.pid and process.env.NODE_DEBUG, // so it needs to be called lazily in top scopes of internal modules // that may be loaded before these run time states are allowed to // be accessed. -/** - * @param {string} set - * @param {DebugLogCallback} cb - * @returns {DebugLogFn} - */ function debuglog(set, cb) { function init() { set = StringPrototypeToUpperCase(set); @@ -151,6 +130,191 @@ function buildCategory(set) { return `node,node.debuglog_${set}`; } +function pad(value) { + return StringPrototypePadStart(`${value}`, 2, '0'); +} + +const kNone = 1 << 0; +const kSkipLog = 1 << 1; +const kSkipTrace = 1 << 2; + +const kSecond = 1000; +const kMinute = 60 * kSecond; +const kHour = 60 * kMinute; + +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`; +} + +/** + * @typedef {(label: string, timeFormatted: string, args?: any[]) => void} LogImpl + */ + +/** + * Returns true if label was found + * @param {string} timesStore + * @param {string} implementation + * @param {LogImpl} logImp + * @param {string} label + * @param {any} args + * @returns {void} + */ +function timeLogImpl(timesStore, implementation, logImp, label, args) { + const time = timesStore.get(label); + if (time === undefined) { + process.emitWarning(`No such label '${label}' for ${implementation}`); + return; + } + + const duration = process.hrtime(time); + const ms = duration[0] * 1000 + duration[1] / 1e6; + + const formatted = formatTime(ms); + + if (args === undefined) { + logImp(label, formatted); + } else { + logImp(label, formatted, args); + } +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {number} timerFlags + * @param {string} logLabel + * @param {string} traceLabel + * @returns {void} + */ +function time(timesStore, traceCategory, implementation, timerFlags, logLabel = 'default', traceLabel = undefined) { + // Coerces everything other than Symbol to a string + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if (timesStore.has(logLabel)) { + process.emitWarning(`Label '${logLabel}' already exists for ${implementation}`); + return; + } + + if ((timerFlags & kSkipTrace) === 0) { + trace(kTraceBegin, traceCategory, traceLabel, 0); + } + + timesStore.set(logLabel, process.hrtime()); +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {number} timerFlags + * @param {LogImpl} logImpl + * @param {string} logLabel + * @param {string} traceLabel + * @returns {void} + */ +function timeEnd( + timesStore, + traceCategory, + implementation, + timerFlags, + logImpl, + logLabel = 'default', + traceLabel = undefined, +) { + // Coerces everything other than Symbol to a string + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if ((timerFlags & kSkipLog) === 0) { + timeLogImpl(timesStore, implementation, logImpl, logLabel); + } + + if ((timerFlags & kSkipTrace) === 0) + trace(kTraceEnd, traceCategory, traceLabel, 0); + + timesStore.delete(logLabel); +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {number} timerFlags + * @param {LogImpl} logImpl + * @param {string} logLabel + * @param {string} traceLabel + * @param {any[]} args + * @returns {void} + */ +function timeLog( + timesStore, + traceCategory, + implementation, + timerFlags, + logImpl, + logLabel = 'default', + traceLabel = undefined, + args, +) { + // Coerces everything other than Symbol to a string + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if ((timerFlags & kSkipLog) === 0) { + timeLogImpl(timesStore, implementation, logImpl, logLabel, args); + } + + if ((timerFlags & kSkipTrace) === 0) { + trace(kTraceInstant, traceCategory, traceLabel, 0); + } +} + /** * @type {Record} */ @@ -182,7 +346,7 @@ function debugWithTimer(set, cb) { } /** - * @type {import('internal/util/trace_timer').LogImpl} + * @type {LogImpl} */ function logImpl(label, timeFormatted, args) { const pid = process.pid; @@ -205,45 +369,53 @@ function debugWithTimer(set, cb) { } const kTraceCategory = buildCategory(StringPrototypeToLowerCase(set)); - /** - * @type {import('internal/util/trace_timer').LogImpl} - */ - let selectedLogImpl; - let categoryEnabled = false; + let debugLogCategoryEnabled = false; + let traceCategoryEnabled = false; + let timerFlags = kNone; /** * @type {TimerStart} */ function internalStartTimer(logLabel, traceLabel) { - if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { - return; - } - - lazyTraceTimer().time(tracesStores[set], kTraceCategory, 'debuglog.time', logLabel, traceLabel); + time( + tracesStores[set], + kTraceCategory, + 'debuglog.time', + timerFlags, + logLabel, + traceLabel, + ); } /** * @type {TimerEnd} */ function internalEndTimer(logLabel, traceLabel) { - if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { - return; - } - - lazyTraceTimer() - .timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, logLabel, traceLabel); + timeEnd( + tracesStores[set], + kTraceCategory, + 'debuglog.timeEnd', + timerFlags, + logImpl, + logLabel, + traceLabel, + ); } /** * @type {TimerLog} */ function internalLogTimer(logLabel, traceLabel, args) { - if (!categoryEnabled && !isTraceCategoryEnabled(kTraceCategory)) { - return; - } - - lazyTraceTimer() - .timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, logLabel, traceLabel, args); + timeLog( + tracesStores[set], + kTraceCategory, + 'debuglog.timeLog', + timerFlags, + logImpl, + logLabel, + traceLabel, + args, + ); } function init() { @@ -251,8 +423,22 @@ function debugWithTimer(set, cb) { tracesStores[set] = new SafeMap(); } emitWarningIfNeeded(set); - categoryEnabled = testEnabled(set); - selectedLogImpl = categoryEnabled ? logImpl : noop; + debugLogCategoryEnabled = testEnabled(set); + traceCategoryEnabled = isTraceCategoryEnabled(kTraceCategory); + + if (!debugLogCategoryEnabled) { + timerFlags |= kSkipLog; + } + + if (!traceCategoryEnabled) { + timerFlags |= kSkipTrace; + } + + // TODO(H4ad): support traceCategory being enabled dynamically + if (debugLogCategoryEnabled || traceCategoryEnabled) + cb(internalStartTimer, internalEndTimer, internalLogTimer); + else + cb(noop, noop, noop); } /** @@ -261,10 +447,8 @@ function debugWithTimer(set, cb) { const startTimer = (logLabel, traceLabel) => { init(); - if (cb) - cb(internalStartTimer, internalEndTimer, internalLogTimer); - - return internalStartTimer(logLabel, traceLabel); + if (debugLogCategoryEnabled || traceCategoryEnabled) + return internalStartTimer(logLabel, traceLabel); }; /** @@ -273,10 +457,8 @@ function debugWithTimer(set, cb) { const endTimer = (logLabel, traceLabel) => { init(); - if (cb) - cb(internalStartTimer, internalEndTimer, internalLogTimer); - - return internalEndTimer(logLabel, traceLabel); + if (debugLogCategoryEnabled || traceCategoryEnabled) + return internalEndTimer(logLabel, traceLabel); }; /** @@ -285,10 +467,8 @@ function debugWithTimer(set, cb) { const logTimer = (logLabel, traceLabel, args) => { init(); - if (cb) - cb(internalStartTimer, internalEndTimer, internalLogTimer); - - return internalLogTimer(logLabel, traceLabel, args); + if (debugLogCategoryEnabled || traceCategoryEnabled) + return internalLogTimer(logLabel, traceLabel, args); }; return { @@ -299,6 +479,13 @@ function debugWithTimer(set, cb) { } module.exports = { + kNone, + kSkipLog, + kSkipTrace, + formatTime, + time, + timeEnd, + timeLog, debuglog, debugWithTimer, initializeDebugEnv, diff --git a/lib/internal/util/trace_timer.js b/lib/internal/util/trace_timer.js deleted file mode 100644 index 06de48f9ebba61..00000000000000 --- a/lib/internal/util/trace_timer.js +++ /dev/null @@ -1,185 +0,0 @@ -'use strict'; - -const { - MathFloor, - NumberPrototypeToFixed, - Number, - StringPrototypeSplit, - StringPrototypePadStart, -} = primordials; - -const { trace } = internalBinding('trace_events'); - -const { - CHAR_LOWERCASE_B: kTraceBegin, - CHAR_LOWERCASE_E: kTraceEnd, - CHAR_LOWERCASE_N: kTraceInstant, -} = require('internal/constants'); - -function pad(value) { - return StringPrototypePadStart(`${value}`, 2, '0'); -} - -const kSecond = 1000; -const kMinute = 60 * kSecond; -const kHour = 60 * kMinute; - -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`; -} - -/** - * @typedef {(label: string, timeFormatted: string, args?: any[]) => void} LogImpl - */ - -/** - * Returns true if label was found - * @param {string} timesStore - * @param {string} implementation - * @param {LogImpl} logImp - * @param {string} label - * @param {any} args - * @returns {boolean} - */ -function timeLogImpl(timesStore, implementation, logImp, label, args) { - const time = timesStore.get(label); - if (time === undefined) { - process.emitWarning(`No such label '${label}' for ${implementation}`); - return false; - } - - const duration = process.hrtime(time); - const ms = duration[0] * 1000 + duration[1] / 1e6; - - const formatted = formatTime(ms); - - if (args === undefined) { - logImp(label, formatted); - } else { - logImp(label, formatted, args); - } - - return true; -} - -/** - * @param {SafeMap} timesStore - * @param {string} traceCategory - * @param {string} implementation - * @param {string} logLabel - * @returns {void} - */ -function time(timesStore, traceCategory, implementation, logLabel = 'default', traceLabel = undefined) { - // Coerces everything other than Symbol to a string - logLabel = `${logLabel}`; - - if (traceLabel !== undefined) { - traceLabel = `${traceLabel}`; - } else { - traceLabel = logLabel; - } - - if (timesStore.has(logLabel)) { - process.emitWarning(`Label '${logLabel}' already exists for ${implementation}`); - return; - } - - trace(kTraceBegin, traceCategory, traceLabel, 0); - timesStore.set(logLabel, process.hrtime()); -} - -/** - * @param {SafeMap} timesStore - * @param {string} traceCategory - * @param {string} implementation - * @param {LogImpl} logImpl - * @param {string} logLabel - * @param {string} traceLabel - * @returns {void} - */ -function timeEnd(timesStore, traceCategory, implementation, logImpl, logLabel = 'default', traceLabel = undefined) { - // Coerces everything other than Symbol to a string - logLabel = `${logLabel}`; - - if (traceLabel !== undefined) { - traceLabel = `${traceLabel}`; - } else { - traceLabel = logLabel; - } - - const found = timeLogImpl(timesStore, implementation, logImpl, logLabel); - trace(kTraceEnd, traceCategory, traceLabel, 0); - - if (found) { - timesStore.delete(logLabel); - } -} - -/** - * @param {SafeMap} timesStore - * @param {string} traceCategory - * @param {string} implementation - * @param {LogImpl} logImpl - * @param {string} logLabel - * @param {string} traceLabel - * @param {any[]} args - * @returns {void} - */ -function timeLog( - timesStore, - traceCategory, - implementation, - logImpl, - logLabel = 'default', - traceLabel = undefined, - args, -) { - // Coerces everything other than Symbol to a string - logLabel = `${logLabel}`; - - if (traceLabel !== undefined) { - traceLabel = `${traceLabel}`; - } else { - traceLabel = logLabel; - } - - timeLogImpl(timesStore, implementation, logImpl, logLabel, args); - - trace(kTraceInstant, traceCategory, traceLabel, 0); -} - -module.exports = { - time, - timeLog, - timeEnd, - formatTime, -}; diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js index 0e337097a98de6..6ce0b761c656a0 100644 --- a/test/parallel/test-console-formatTime.js +++ b/test/parallel/test-console-formatTime.js @@ -1,7 +1,7 @@ 'use strict'; // Flags: --expose-internals require('../common'); -const { formatTime } = require('internal/util/trace_timer'); +const { formatTime } = require('internal/util/debuglog'); const assert = require('assert'); assert.strictEqual(formatTime(100.0096), '100.01ms'); diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index b0f6b86a609607..516a37e2567e73 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -1,8 +1,12 @@ import { spawnPromisified } from '../common/index.mjs'; +import tmpdir from '../common/tmpdir.js'; import assert from 'node:assert'; +import { readFile } from 'node:fs/promises'; import { execPath } from 'node:process'; import { it } from 'node:test'; +tmpdir.refresh(); + it('should print the timing information for cjs', async () => { const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], { env: { @@ -21,3 +25,67 @@ it('should print the timing information for cjs', async () => { assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); }); + +it('should write tracing information for cjs', async () => { + const outputFile = tmpdir.resolve('output-trace.log'); + const result = await spawnPromisified(execPath, [ + '--trace-event-categories', + 'node.debuglog_module_cjs', + '--trace-event-file-pattern', + outputFile, + '--eval', + 'require("url");', + ]); + + assert.strictEqual(result.code, 0); + assert.strictEqual(result.signal, null); + assert.strictEqual(result.stdout, ''); + assert.strictEqual(result.stderr, ''); + + const expectedMimeTypes = ['b', 'e']; + const outputFileContent = await readFile(outputFile, 'utf-8'); + const outputFileJson = JSON.parse(outputFileContent).traceEvents; + const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')"); + + assert.strictEqual(urlTraces.length, 2); + + for (const trace of urlTraces) { + assert.strictEqual(trace.ph, expectedMimeTypes.shift()); + } +}); + +it('should write tracing & print logs for cjs', async () => { + const outputFile = tmpdir.resolve('output-trace-and-log.log'); + const result = await spawnPromisified(execPath, [ + '--trace-event-categories', + 'node.debuglog_module_cjs', + '--trace-event-file-pattern', + outputFile, + '--eval', + 'require("url");', + ], { + env: { + NODE_DEBUG: 'module_cjs', + }, + }); + + 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('MODULE_CJS'), `Not found MODULE_CJS on ${firstLine}`); + assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); + assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); + + const expectedMimeTypes = ['b', 'e']; + const outputFileContent = await readFile(outputFile, 'utf-8'); + const outputFileJson = JSON.parse(outputFileContent).traceEvents; + const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')"); + + for (const trace of urlTraces) { + assert.strictEqual(trace.ph, expectedMimeTypes.shift()); + } +}); From 956b75ae9d5efb760fa5bae7a51354d662f3a4ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 9 Apr 2024 21:45:23 -0300 Subject: [PATCH 08/29] remove unecessary changes --- lib/internal/console/constructor.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 3c9a2aa8f1cda2..4a90ba387e9fe0 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -529,9 +529,9 @@ const consoleMethods = { const _inspect = (v) => { const depth = v !== null && - typeof v === 'object' && - !isArray(v) && - ObjectKeys(v).length > 2 ? -1 : 0; + typeof v === 'object' && + !isArray(v) && + ObjectKeys(v).length > 2 ? -1 : 0; const opt = { depth, maxArrayLength: 3, @@ -601,7 +601,7 @@ const consoleMethods = { for (; i < indexKeyArray.length; i++) { const item = tabularData[indexKeyArray[i]]; const primitive = item === null || - (typeof item !== 'function' && typeof item !== 'object'); + (typeof item !== 'function' && typeof item !== 'object'); if (properties === undefined && primitive) { hasPrimitives = true; valuesKeyArray[i] = _inspect(item); @@ -610,7 +610,7 @@ const consoleMethods = { for (const key of keys) { map[key] ??= []; if ((primitive && properties) || - !ObjectPrototypeHasOwnProperty(item, key)) + !ObjectPrototypeHasOwnProperty(item, key)) map[key][i] = ''; else map[key][i] = _inspect(item[key]); @@ -638,7 +638,7 @@ const iterKey = '(iteration index)'; const isArray = (v) => ArrayIsArray(v) || isTypedArray(v) || isBuffer(v); -function noop() { } +function noop() {} for (const method of ReflectOwnKeys(consoleMethods)) Console.prototype[method] = consoleMethods[method]; From cdc1629fbb8ac9ca3402ee67aa67cf59dca694c3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 9 Apr 2024 21:45:54 -0300 Subject: [PATCH 09/29] remove unecessary changes --- lib/internal/console/constructor.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 4a90ba387e9fe0..0ada75bf49edb5 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -610,7 +610,7 @@ const consoleMethods = { for (const key of keys) { map[key] ??= []; if ((primitive && properties) || - !ObjectPrototypeHasOwnProperty(item, key)) + !ObjectPrototypeHasOwnProperty(item, key)) map[key][i] = ''; else map[key][i] = _inspect(item[key]); From cd4fb610b4cb315e745ca90070da40512c916626 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 9 Apr 2024 21:50:35 -0300 Subject: [PATCH 10/29] resolve rebase conflicts --- lib/internal/modules/cjs/loader.js | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 404bcbff5fc11f..3bb80ec7076d45 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -1051,7 +1051,11 @@ Module._load = function(request, parent, isMain) { // came from imported CJS. In that case use the kModuleCircularVisited // to determine if it's loading or not. if (cachedModule[kModuleCircularVisited]) { - return getExportsForCircularRequire(cachedModule); + const result = getExportsForCircularRequire(cachedModule); + + endTimer(logLabel, traceLabel); + + return result; } // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. endTimer(logLabel, traceLabel); From 108be09e70e45f1be2f7553dee2bb1631531ef2c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Fri, 12 Apr 2024 18:20:29 -0300 Subject: [PATCH 11/29] fixing nits --- lib/internal/console/constructor.js | 23 ++++------------------- lib/internal/modules/cjs/loader.js | 4 ++++ lib/internal/util/debuglog.js | 12 ++++-------- 3 files changed, 12 insertions(+), 27 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 0ada75bf49edb5..26449a75bf7cb8 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -62,22 +62,10 @@ const { } = 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'; -let _debugLog; -/** - * @returns {import('internal/util/debuglog')} - */ -function lazyDebugLog() { - if (_debugLog) { - return _debugLog; - } - - _debugLog = require('internal/util/debuglog'); - return _debugLog; -} - const kMaxGroupIndentation = 1000; // Lazy loaded for startup performance. @@ -415,24 +403,21 @@ const consoleMethods = { }, time(label = 'default') { - lazyDebugLog() - .time(this._times, kTraceConsoleCategory, 'console.time()', lazyDebugLog().kNone, label, `time::${label}`); + time(this._times, kTraceConsoleCategory, 'console.time()', kNone, label, `time::${label}`); }, timeEnd(label = 'default') { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - lazyDebugLog() - .timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', lazyDebugLog().kNone, this[kInternalTimeLogImpl], label, `time::${label}`); + timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`); }, timeLog(label = 'default', ...data) { if (this[kInternalTimeLogImpl] === undefined) this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); - lazyDebugLog() - .timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', lazyDebugLog().kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data); + timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data); }, trace: function trace(...args) { diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 3bb80ec7076d45..f4fd2b49a62905 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -1020,6 +1020,8 @@ Module._load = function(request, parent, isMain) { const id = StringPrototypeSlice(request, 5); if (!BuiltinModule.canBeRequiredByUsers(id)) { + endTimer(logLabel, traceLabel); + throw new ERR_UNKNOWN_BUILTIN_MODULE(request); } @@ -1109,6 +1111,8 @@ Module._load = function(request, parent, isMain) { } } } + + endTimer(logLabel, traceLabel); } else if (module.exports && !isProxy(module.exports) && ObjectGetPrototypeOf(module.exports) === diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 2ad38bc5f27f53..1f14b532ac573c 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -126,10 +126,6 @@ function debuglog(set, cb) { return logger; } -function buildCategory(set) { - return `node,node.debuglog_${set}`; -} - function pad(value) { return StringPrototypePadStart(`${value}`, 2, '0'); } @@ -368,7 +364,7 @@ function debugWithTimer(set, cb) { ); } - const kTraceCategory = buildCategory(StringPrototypeToLowerCase(set)); + const kTraceCategory = `node,node.debuglog_${StringPrototypeToLowerCase(set)}`; let debugLogCategoryEnabled = false; let traceCategoryEnabled = false; let timerFlags = kNone; @@ -448,7 +444,7 @@ function debugWithTimer(set, cb) { init(); if (debugLogCategoryEnabled || traceCategoryEnabled) - return internalStartTimer(logLabel, traceLabel); + internalStartTimer(logLabel, traceLabel); }; /** @@ -458,7 +454,7 @@ function debugWithTimer(set, cb) { init(); if (debugLogCategoryEnabled || traceCategoryEnabled) - return internalEndTimer(logLabel, traceLabel); + internalEndTimer(logLabel, traceLabel); }; /** @@ -468,7 +464,7 @@ function debugWithTimer(set, cb) { init(); if (debugLogCategoryEnabled || traceCategoryEnabled) - return internalLogTimer(logLabel, traceLabel, args); + internalLogTimer(logLabel, traceLabel, args); }; return { From ba734f06637b271918b2d75aedf5ee925ed2cd31 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Fri, 12 Apr 2024 18:26:05 -0300 Subject: [PATCH 12/29] resolve conflicts after rebase --- lib/internal/modules/cjs/loader.js | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index f4fd2b49a62905..1b9405cc134142 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -1036,6 +1036,8 @@ Module._load = function(request, parent, isMain) { if (cachedModule !== undefined) { updateChildren(parent, cachedModule, true); if (cachedModule.loaded) { + endTimer(logLabel, traceLabel); + return cachedModule.exports; } // If it's not cached by the ESM loader, the loading request @@ -1044,9 +1046,9 @@ Module._load = function(request, parent, isMain) { if (!cachedModule[kIsCachedByESMLoader]) { const result = getExportsForCircularRequire(cachedModule); - endTimer(logLabel, traceLabel); + endTimer(logLabel, traceLabel); - return result; + return result; } // If it's cached by the ESM loader as a way to indirectly pass // the module in to avoid creating it twice, the loading request @@ -1055,9 +1057,9 @@ Module._load = function(request, parent, isMain) { if (cachedModule[kModuleCircularVisited]) { const result = getExportsForCircularRequire(cachedModule); - endTimer(logLabel, traceLabel); + endTimer(logLabel, traceLabel); - return result; + return result; } // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. endTimer(logLabel, traceLabel); From b04cfc5d47909f6adba760ba8fa63b88233e76c3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Fri, 12 Apr 2024 18:36:06 -0300 Subject: [PATCH 13/29] fix lint issues --- lib/internal/console/constructor.js | 2 +- lib/internal/modules/cjs/loader.js | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 26449a75bf7cb8..9e400e8e4f2263 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -138,7 +138,7 @@ function Console(options /* or: stdout, stderr, ignoreErrors = true */) { validateObject(inspectOptions, 'options.inspectOptions'); if (inspectOptions.colors !== undefined && - options.colorMode !== undefined) { + options.colorMode !== undefined) { throw new ERR_INCOMPATIBLE_OPTION_PAIR( 'options.inspectOptions.color', 'colorMode'); } diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 1b9405cc134142..e8cea3d90d514b 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -1062,7 +1062,6 @@ Module._load = function(request, parent, isMain) { return result; } // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. - endTimer(logLabel, traceLabel); cachedModule[kModuleCircularVisited] = true; } From b426ede1fce72281faac691498eec9adb48406d9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 13 Apr 2024 16:45:01 -0300 Subject: [PATCH 14/29] handle unexpected errors during _load --- lib/internal/modules/cjs/loader.js | 209 +++++++++++++---------------- 1 file changed, 95 insertions(+), 114 deletions(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index e8cea3d90d514b..7f3e71d5fa6548 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -987,144 +987,125 @@ Module._load = function(request, parent, isMain) { startTimer(logLabel, traceLabel); - let relResolveCacheIdentifier; - if (parent) { - debug('Module._load REQUEST %s parent: %s', request, parent.id); - // Fast path for (lazy loaded) modules in the same directory. The indirect - // caching is required to allow cache invalidation without changing the old - // cache key names. - relResolveCacheIdentifier = `${parent.path}\x00${request}`; - const filename = relativeResolveCache[relResolveCacheIdentifier]; - reportModuleToWatchMode(filename); - if (filename !== undefined) { - const cachedModule = Module._cache[filename]; - if (cachedModule !== undefined) { - updateChildren(parent, cachedModule, true); - if (!cachedModule.loaded) { - const result = getExportsForCircularRequire(cachedModule); - - endTimer(logLabel, traceLabel); - - return result; - } - - endTimer(logLabel, traceLabel); - return cachedModule.exports; - } - delete relativeResolveCache[relResolveCacheIdentifier]; - } - } - - if (StringPrototypeStartsWith(request, 'node:')) { - // Slice 'node:' prefix - const id = StringPrototypeSlice(request, 5); + try { + let relResolveCacheIdentifier; - if (!BuiltinModule.canBeRequiredByUsers(id)) { - endTimer(logLabel, traceLabel); + if (parent) { + debug('Module._load REQUEST %s parent: %s', request, parent.id); + // Fast path for (lazy loaded) modules in the same directory. The indirect + // caching is required to allow cache invalidation without changing the old + // cache key names. + relResolveCacheIdentifier = `${parent.path}\x00${request}`; + const filename = relativeResolveCache[relResolveCacheIdentifier]; + reportModuleToWatchMode(filename); + if (filename !== undefined) { + const cachedModule = Module._cache[filename]; + if (cachedModule !== undefined) { + updateChildren(parent, cachedModule, true); + if (!cachedModule.loaded) { + return getExportsForCircularRequire(cachedModule); + } - throw new ERR_UNKNOWN_BUILTIN_MODULE(request); + return cachedModule.exports; + } + delete relativeResolveCache[relResolveCacheIdentifier]; + } } - const module = loadBuiltinModule(id, request); + if (StringPrototypeStartsWith(request, 'node:')) { + // Slice 'node:' prefix + const id = StringPrototypeSlice(request, 5); - endTimer(logLabel, traceLabel); - return module.exports; - } + if (!BuiltinModule.canBeRequiredByUsers(id)) { + throw new ERR_UNKNOWN_BUILTIN_MODULE(request); + } - const filename = Module._resolveFilename(request, parent, isMain); - const cachedModule = Module._cache[filename]; - if (cachedModule !== undefined) { - updateChildren(parent, cachedModule, true); - if (cachedModule.loaded) { - endTimer(logLabel, traceLabel); + const module = loadBuiltinModule(id, request); - return cachedModule.exports; + return module.exports; } - // If it's not cached by the ESM loader, the loading request - // comes from required CJS, and we can consider it a circular - // dependency when it's cached. - if (!cachedModule[kIsCachedByESMLoader]) { - const result = getExportsForCircularRequire(cachedModule); - - endTimer(logLabel, traceLabel); - return result; + const filename = Module._resolveFilename(request, parent, isMain); + const cachedModule = Module._cache[filename]; + if (cachedModule !== undefined) { + updateChildren(parent, cachedModule, true); + if (cachedModule.loaded) { + return cachedModule.exports; + } + // If it's not cached by the ESM loader, the loading request + // comes from required CJS, and we can consider it a circular + // dependency when it's cached. + if (!cachedModule[kIsCachedByESMLoader]) { + return getExportsForCircularRequire(cachedModule); + } + // If it's cached by the ESM loader as a way to indirectly pass + // the module in to avoid creating it twice, the loading request + // came from imported CJS. In that case use the kModuleCircularVisited + // to determine if it's loading or not. + if (cachedModule[kModuleCircularVisited]) { + return getExportsForCircularRequire(cachedModule); + } + // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. + cachedModule[kModuleCircularVisited] = true; } - // If it's cached by the ESM loader as a way to indirectly pass - // the module in to avoid creating it twice, the loading request - // came from imported CJS. In that case use the kModuleCircularVisited - // to determine if it's loading or not. - if (cachedModule[kModuleCircularVisited]) { - const result = getExportsForCircularRequire(cachedModule); - endTimer(logLabel, traceLabel); + if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { + const mod = loadBuiltinModule(filename, request); - return result; + return mod.exports; } - // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. - cachedModule[kModuleCircularVisited] = true; - } - if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { - const mod = loadBuiltinModule(filename, request); + // Don't call updateChildren(), Module constructor already does. + const module = cachedModule || new Module(filename, parent); - endTimer(logLabel, traceLabel); - - return mod.exports; - } - - // Don't call updateChildren(), Module constructor already does. - const module = cachedModule || new Module(filename, parent); + if (!cachedModule) { + if (isMain) { + setOwnProperty(process, 'mainModule', module); + setOwnProperty(module.require, 'main', process.mainModule); + module.id = '.'; + module[kIsMainSymbol] = true; + } else { + module[kIsMainSymbol] = false; + } - if (!cachedModule) { - if (isMain) { - setOwnProperty(process, 'mainModule', module); - setOwnProperty(module.require, 'main', process.mainModule); - module.id = '.'; - module[kIsMainSymbol] = true; - } else { - module[kIsMainSymbol] = false; + reportModuleToWatchMode(filename); + Module._cache[filename] = module; + module[kIsCachedByESMLoader] = false; } - reportModuleToWatchMode(filename); - Module._cache[filename] = module; - module[kIsCachedByESMLoader] = false; - } - - if (parent !== undefined) { - relativeResolveCache[relResolveCacheIdentifier] = filename; - } + if (parent !== undefined) { + relativeResolveCache[relResolveCacheIdentifier] = filename; + } - let threw = true; - try { - module.load(filename); - threw = false; - } finally { - if (threw) { - delete Module._cache[filename]; - if (parent !== undefined) { - delete relativeResolveCache[relResolveCacheIdentifier]; - const children = parent?.children; - if (ArrayIsArray(children)) { - const index = ArrayPrototypeIndexOf(children, module); - if (index !== -1) { - ArrayPrototypeSplice(children, index, 1); + let threw = true; + try { + module.load(filename); + threw = false; + } finally { + if (threw) { + delete Module._cache[filename]; + if (parent !== undefined) { + delete relativeResolveCache[relResolveCacheIdentifier]; + const children = parent?.children; + if (ArrayIsArray(children)) { + const index = ArrayPrototypeIndexOf(children, module); + if (index !== -1) { + ArrayPrototypeSplice(children, index, 1); + } } } + } else if (module.exports && + !isProxy(module.exports) && + ObjectGetPrototypeOf(module.exports) === + CircularRequirePrototypeWarningProxy) { + ObjectSetPrototypeOf(module.exports, ObjectPrototype); } - - endTimer(logLabel, traceLabel); - } else if (module.exports && - !isProxy(module.exports) && - ObjectGetPrototypeOf(module.exports) === - CircularRequirePrototypeWarningProxy) { - ObjectSetPrototypeOf(module.exports, ObjectPrototype); } - } - - endTimer(logLabel, traceLabel); - return module.exports; + return module.exports; + } finally { + endTimer(logLabel, traceLabel); + } }; /** From 2c2a6ef6dbb3f2e02433aab533ed5c87de9bb8ed Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 21:17:20 -0300 Subject: [PATCH 15/29] add wrap module load function --- lib/internal/modules/cjs/loader.js | 240 +++++++++++++++-------------- lib/internal/util/debuglog.js | 4 +- 2 files changed, 126 insertions(+), 118 deletions(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 7f3e71d5fa6548..401c0d21c5bd6d 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -181,6 +181,13 @@ const { isProxy, } = require('internal/util/types'); +const { debuglog, debugWithTimer } = require('internal/util/debuglog'); + +let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => { + startTimer = start; + endTimer = end; +}); + const isWindows = process.platform === 'win32'; const relativeResolveCache = { __proto__: null }; @@ -189,6 +196,28 @@ let requireDepth = 0; let isPreloading = false; let statCache = null; +/** + * Internal method to be able to add recursion & tracing capabilities + * for Module._load. + * + * See more {@link Module._load} + */ +function wrapModuleLoad(request, parent, isMain) { + const logLabel = `[${parent?.id || ''}] [${request}]`; + const traceLabel = `require('${request}')`; + + requireDepth++; + + startTimer(logLabel, traceLabel); + + try { + return Module._load(request, parent, isMain); + } finally { + requireDepth--; + endTimer(logLabel, traceLabel); + } +} + /** * Get a path's properties, using an in-memory cache to minimize lookups. * @param {string} filename Absolute path to the file @@ -354,17 +383,10 @@ function setModuleParent(value) { this[kModuleParent] = value; } -const { debuglog, debugWithTimer } = require('internal/util/debuglog'); - let debug = debuglog('module', (fn) => { debug = fn; }); -let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => { - startTimer = start; - endTimer = end; -}); - ObjectDefineProperty(Module.prototype, 'parent', { __proto__: null, get: pendingDeprecate( @@ -982,130 +1004,121 @@ function getExportsForCircularRequire(module) { * @param {boolean} isMain Whether the module is the main entry point */ Module._load = function(request, parent, isMain) { - const logLabel = `[${parent?.id || ''}] [${request}]`; - const traceLabel = `require('${request}')`; - - startTimer(logLabel, traceLabel); - - try { - let relResolveCacheIdentifier; - - if (parent) { - debug('Module._load REQUEST %s parent: %s', request, parent.id); - // Fast path for (lazy loaded) modules in the same directory. The indirect - // caching is required to allow cache invalidation without changing the old - // cache key names. - relResolveCacheIdentifier = `${parent.path}\x00${request}`; - const filename = relativeResolveCache[relResolveCacheIdentifier]; - reportModuleToWatchMode(filename); - if (filename !== undefined) { - const cachedModule = Module._cache[filename]; - if (cachedModule !== undefined) { - updateChildren(parent, cachedModule, true); - if (!cachedModule.loaded) { - return getExportsForCircularRequire(cachedModule); - } - - return cachedModule.exports; + let relResolveCacheIdentifier; + + if (parent) { + debug('Module._load REQUEST %s parent: %s', request, parent.id); + // Fast path for (lazy loaded) modules in the same directory. The indirect + // caching is required to allow cache invalidation without changing the old + // cache key names. + relResolveCacheIdentifier = `${parent.path}\x00${request}`; + const filename = relativeResolveCache[relResolveCacheIdentifier]; + reportModuleToWatchMode(filename); + if (filename !== undefined) { + const cachedModule = Module._cache[filename]; + if (cachedModule !== undefined) { + updateChildren(parent, cachedModule, true); + if (!cachedModule.loaded) { + return getExportsForCircularRequire(cachedModule); } - delete relativeResolveCache[relResolveCacheIdentifier]; - } - } - - if (StringPrototypeStartsWith(request, 'node:')) { - // Slice 'node:' prefix - const id = StringPrototypeSlice(request, 5); - if (!BuiltinModule.canBeRequiredByUsers(id)) { - throw new ERR_UNKNOWN_BUILTIN_MODULE(request); + return cachedModule.exports; } + delete relativeResolveCache[relResolveCacheIdentifier]; + } + } - const module = loadBuiltinModule(id, request); + if (StringPrototypeStartsWith(request, 'node:')) { + // Slice 'node:' prefix + const id = StringPrototypeSlice(request, 5); - return module.exports; + if (!BuiltinModule.canBeRequiredByUsers(id)) { + throw new ERR_UNKNOWN_BUILTIN_MODULE(request); } - const filename = Module._resolveFilename(request, parent, isMain); - const cachedModule = Module._cache[filename]; - if (cachedModule !== undefined) { - updateChildren(parent, cachedModule, true); - if (cachedModule.loaded) { - return cachedModule.exports; - } - // If it's not cached by the ESM loader, the loading request - // comes from required CJS, and we can consider it a circular - // dependency when it's cached. - if (!cachedModule[kIsCachedByESMLoader]) { - return getExportsForCircularRequire(cachedModule); - } - // If it's cached by the ESM loader as a way to indirectly pass - // the module in to avoid creating it twice, the loading request - // came from imported CJS. In that case use the kModuleCircularVisited - // to determine if it's loading or not. - if (cachedModule[kModuleCircularVisited]) { - return getExportsForCircularRequire(cachedModule); - } - // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. - cachedModule[kModuleCircularVisited] = true; - } + const module = loadBuiltinModule(id, request); - if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { - const mod = loadBuiltinModule(filename, request); + return module.exports; + } - return mod.exports; + const filename = Module._resolveFilename(request, parent, isMain); + const cachedModule = Module._cache[filename]; + if (cachedModule !== undefined) { + updateChildren(parent, cachedModule, true); + if (cachedModule.loaded) { + return cachedModule.exports; + } + // If it's not cached by the ESM loader, the loading request + // comes from required CJS, and we can consider it a circular + // dependency when it's cached. + if (!cachedModule[kIsCachedByESMLoader]) { + return getExportsForCircularRequire(cachedModule); } + // If it's cached by the ESM loader as a way to indirectly pass + // the module in to avoid creating it twice, the loading request + // came from imported CJS. In that case use the kModuleCircularVisited + // to determine if it's loading or not. + if (cachedModule[kModuleCircularVisited]) { + return getExportsForCircularRequire(cachedModule); + } + // This is an ESM loader created cache entry, mark it as visited and fallthrough to loading the module. + cachedModule[kModuleCircularVisited] = true; + } - // Don't call updateChildren(), Module constructor already does. - const module = cachedModule || new Module(filename, parent); + if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { + const mod = loadBuiltinModule(filename, request); - if (!cachedModule) { - if (isMain) { - setOwnProperty(process, 'mainModule', module); - setOwnProperty(module.require, 'main', process.mainModule); - module.id = '.'; - module[kIsMainSymbol] = true; - } else { - module[kIsMainSymbol] = false; - } + return mod.exports; + } - reportModuleToWatchMode(filename); - Module._cache[filename] = module; - module[kIsCachedByESMLoader] = false; - } + // Don't call updateChildren(), Module constructor already does. + const module = cachedModule || new Module(filename, parent); - if (parent !== undefined) { - relativeResolveCache[relResolveCacheIdentifier] = filename; + if (!cachedModule) { + if (isMain) { + setOwnProperty(process, 'mainModule', module); + setOwnProperty(module.require, 'main', process.mainModule); + module.id = '.'; + module[kIsMainSymbol] = true; + } else { + module[kIsMainSymbol] = false; } - let threw = true; - try { - module.load(filename); - threw = false; - } finally { - if (threw) { - delete Module._cache[filename]; - if (parent !== undefined) { - delete relativeResolveCache[relResolveCacheIdentifier]; - const children = parent?.children; - if (ArrayIsArray(children)) { - const index = ArrayPrototypeIndexOf(children, module); - if (index !== -1) { - ArrayPrototypeSplice(children, index, 1); - } + reportModuleToWatchMode(filename); + Module._cache[filename] = module; + module[kIsCachedByESMLoader] = false; + } + + if (parent !== undefined) { + relativeResolveCache[relResolveCacheIdentifier] = filename; + } + + let threw = true; + try { + module.load(filename); + threw = false; + } finally { + if (threw) { + delete Module._cache[filename]; + if (parent !== undefined) { + delete relativeResolveCache[relResolveCacheIdentifier]; + const children = parent?.children; + if (ArrayIsArray(children)) { + const index = ArrayPrototypeIndexOf(children, module); + if (index !== -1) { + ArrayPrototypeSplice(children, index, 1); } } - } else if (module.exports && - !isProxy(module.exports) && - ObjectGetPrototypeOf(module.exports) === - CircularRequirePrototypeWarningProxy) { - ObjectSetPrototypeOf(module.exports, ObjectPrototype); } + } else if (module.exports && + !isProxy(module.exports) && + ObjectGetPrototypeOf(module.exports) === + CircularRequirePrototypeWarningProxy) { + ObjectSetPrototypeOf(module.exports, ObjectPrototype); } - - return module.exports; - } finally { - endTimer(logLabel, traceLabel); } + + return module.exports; }; /** @@ -1286,12 +1299,7 @@ Module.prototype.require = function(id) { throw new ERR_INVALID_ARG_VALUE('id', id, 'must be a non-empty string'); } - requireDepth++; - try { - return Module._load(id, this, /* isMain */ false); - } finally { - requireDepth--; - } + return wrapModuleLoad(id, this, false); }; /** diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 1f14b532ac573c..5668a61a6d3684 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -321,11 +321,11 @@ let tracesStores; */ /** - * @typedef {(label: string, traceLabel?: string) => void} TimerEnd + * @typedef {(logLabel: string, traceLabel?: string) => void} TimerEnd */ /** - * @typedef {(label: string, traceLabel?: string, args?: any[]) => void} TimerLog + * @typedef {(logLabel: string, traceLabel?: string, args?: any[]) => void} TimerLog */ /** From 61a94afad4657183de0c2f6919cc5d8dc3713787 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Sat, 13 Apr 2024 20:22:40 -0300 Subject: [PATCH 16/29] removed unused spaces --- lib/internal/modules/cjs/loader.js | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 401c0d21c5bd6d..e530a0bf91f129 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -1005,7 +1005,6 @@ function getExportsForCircularRequire(module) { */ Module._load = function(request, parent, isMain) { let relResolveCacheIdentifier; - if (parent) { debug('Module._load REQUEST %s parent: %s', request, parent.id); // Fast path for (lazy loaded) modules in the same directory. The indirect @@ -1021,7 +1020,6 @@ Module._load = function(request, parent, isMain) { if (!cachedModule.loaded) { return getExportsForCircularRequire(cachedModule); } - return cachedModule.exports; } delete relativeResolveCache[relResolveCacheIdentifier]; @@ -1037,7 +1035,6 @@ Module._load = function(request, parent, isMain) { } const module = loadBuiltinModule(id, request); - return module.exports; } @@ -1067,7 +1064,6 @@ Module._load = function(request, parent, isMain) { if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { const mod = loadBuiltinModule(filename, request); - return mod.exports; } @@ -1111,9 +1107,9 @@ Module._load = function(request, parent, isMain) { } } } else if (module.exports && - !isProxy(module.exports) && - ObjectGetPrototypeOf(module.exports) === - CircularRequirePrototypeWarningProxy) { + !isProxy(module.exports) && + ObjectGetPrototypeOf(module.exports) === + CircularRequirePrototypeWarningProxy) { ObjectSetPrototypeOf(module.exports, ObjectPrototype); } } @@ -1299,7 +1295,7 @@ Module.prototype.require = function(id) { throw new ERR_INVALID_ARG_VALUE('id', id, 'must be a non-empty string'); } - return wrapModuleLoad(id, this, false); + return wrapModuleLoad(id, this, /** isMain */ false); }; /** From 9f46a21e2135d92c3cfcc30cdbe1deda9569bd7e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 21:18:04 -0300 Subject: [PATCH 17/29] fixing tests on last modification --- lib/internal/modules/cjs/loader.js | 4 +-- lib/internal/modules/esm/translators.js | 7 +++-- lib/internal/modules/run_main.js | 4 +-- lib/internal/util/debuglog.js | 6 ++-- test/fixtures/console/console.snapshot | 1 + test/fixtures/errors/force_colors.snapshot | 1 + .../promise_always_throw_unhandled.snapshot | 1 + ...promise_unhandled_warn_with_error.snapshot | 1 + .../unhandled_promise_trace_warnings.snapshot | 1 + .../test-runner/output/abort.snapshot | 2 ++ .../test-runner/output/abort_suite.snapshot | 1 + test/message/assert_throws_stack.out | 1 + test/message/internal_assert.out | 1 + test/message/internal_assert_fail.out | 1 + test/message/util-inspect-error-cause.out | 30 ++++++++++++------- test/message/util_inspect_error.out | 5 ++++ test/parallel/test-repl.js | 1 + test/pseudo-tty/console_colors.out | 3 +- test/pseudo-tty/test-fatal-error.out | 1 + test/pseudo-tty/test-trace-sigint.out | 1 + 20 files changed, 51 insertions(+), 22 deletions(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index e530a0bf91f129..f7093f0f92ec39 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -108,6 +108,7 @@ module.exports = { initializeCJS, Module, wrapSafe, + wrapModuleLoad, kIsMainSymbol, kIsCachedByESMLoader, kRequiredModuleSymbol, @@ -206,14 +207,11 @@ function wrapModuleLoad(request, parent, isMain) { const logLabel = `[${parent?.id || ''}] [${request}]`; const traceLabel = `require('${request}')`; - requireDepth++; - startTimer(logLabel, traceLabel); try { return Module._load(request, parent, isMain); } finally { - requireDepth--; endTimer(logLabel, traceLabel); } } diff --git a/lib/internal/modules/esm/translators.js b/lib/internal/modules/esm/translators.js index 89754b6453dbcc..ea6a9dbd8a9440 100644 --- a/lib/internal/modules/esm/translators.js +++ b/lib/internal/modules/esm/translators.js @@ -43,6 +43,7 @@ const { const { kIsCachedByESMLoader, Module: CJSModule, + wrapModuleLoad, kModuleSource, kModuleExport, kModuleExportNames, @@ -198,7 +199,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 } @@ -290,7 +291,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); }); }); @@ -315,7 +316,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 { diff --git a/lib/internal/modules/run_main.js b/lib/internal/modules/run_main.js index 7b26b67bfd4cd6..6c5601ed458b89 100644 --- a/lib/internal/modules/run_main.js +++ b/lib/internal/modules/run_main.js @@ -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) { diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 5668a61a6d3684..feb690c8f40ff1 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -1,18 +1,18 @@ 'use strict'; const { + MathFloor, Number, NumberPrototypeToFixed, - MathFloor, ObjectDefineProperty, RegExp, RegExpPrototypeExec, SafeArrayIterator, SafeMap, + StringPrototypePadStart, + StringPrototypeSplit, StringPrototypeToLowerCase, StringPrototypeToUpperCase, - StringPrototypeSplit, - StringPrototypePadStart, } = primordials; const { CHAR_LOWERCASE_B: kTraceBegin, diff --git a/test/fixtures/console/console.snapshot b/test/fixtures/console/console.snapshot index 9aabbe5c5f275a..4f1cb254811b6d 100644 --- a/test/fixtures/console/console.snapshot +++ b/test/fixtures/console/console.snapshot @@ -6,3 +6,4 @@ Trace: foo at * at * at * + at * diff --git a/test/fixtures/errors/force_colors.snapshot b/test/fixtures/errors/force_colors.snapshot index 3624d9f0804545..21410d492db861 100644 --- a/test/fixtures/errors/force_colors.snapshot +++ b/test/fixtures/errors/force_colors.snapshot @@ -10,5 +10,6 @@ Error: Should include grayed stack trace  at *  at *  at * + at * Node.js * diff --git a/test/fixtures/errors/promise_always_throw_unhandled.snapshot b/test/fixtures/errors/promise_always_throw_unhandled.snapshot index c97540f5499f87..cf42c69efdc372 100644 --- a/test/fixtures/errors/promise_always_throw_unhandled.snapshot +++ b/test/fixtures/errors/promise_always_throw_unhandled.snapshot @@ -12,5 +12,6 @@ Error: One at * at * at * + at * Node.js * diff --git a/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot b/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot index d7f1aa2f72007f..48e5da7c9aded5 100644 --- a/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot +++ b/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot @@ -6,5 +6,6 @@ at * at * at * + at * (Use `node --trace-warnings ...` to show where the warning was created) (node:*) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https:*nodejs.org*api*cli.html#cli_unhandled_rejections_mode). (rejection id: 1) diff --git a/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot b/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot index bf50fffd60c5ee..c95df6d5aa056d 100644 --- a/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot +++ b/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot @@ -18,6 +18,7 @@ at * at * at * + at * (node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1) at * at * diff --git a/test/fixtures/test-runner/output/abort.snapshot b/test/fixtures/test-runner/output/abort.snapshot index 1b758a2314c486..be0936bd763fbb 100644 --- a/test/fixtures/test-runner/output/abort.snapshot +++ b/test/fixtures/test-runner/output/abort.snapshot @@ -135,6 +135,7 @@ not ok 2 - promise abort signal * * * + * ... # Subtest: callback timeout signal # Subtest: ok 1 @@ -272,6 +273,7 @@ not ok 4 - callback abort signal * * * + * ... 1..4 # tests 22 diff --git a/test/fixtures/test-runner/output/abort_suite.snapshot b/test/fixtures/test-runner/output/abort_suite.snapshot index 30d48d236ff4a5..b3eb5d9126db26 100644 --- a/test/fixtures/test-runner/output/abort_suite.snapshot +++ b/test/fixtures/test-runner/output/abort_suite.snapshot @@ -137,6 +137,7 @@ not ok 2 - describe abort signal * * * + * ... 1..2 # tests 9 diff --git a/test/message/assert_throws_stack.out b/test/message/assert_throws_stack.out index 06eaa906442440..652a60532c68d5 100644 --- a/test/message/assert_throws_stack.out +++ b/test/message/assert_throws_stack.out @@ -15,6 +15,7 @@ AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal: at * at * at * + at * at * { generatedMessage: true, code: 'ERR_ASSERTION', diff --git a/test/message/internal_assert.out b/test/message/internal_assert.out index 197b863bf6ae69..e4f67f650f938e 100644 --- a/test/message/internal_assert.out +++ b/test/message/internal_assert.out @@ -12,6 +12,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss at * at * at * + at * at * { code: 'ERR_INTERNAL_ASSERTION' } diff --git a/test/message/internal_assert_fail.out b/test/message/internal_assert_fail.out index e6895691cda9c1..6a5916401bb7f6 100644 --- a/test/message/internal_assert_fail.out +++ b/test/message/internal_assert_fail.out @@ -13,6 +13,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss at * at * at * + at * at * { code: 'ERR_INTERNAL_ASSERTION' } diff --git a/test/message/util-inspect-error-cause.out b/test/message/util-inspect-error-cause.out index 73f0a673d76e1f..344ace1bc94074 100644 --- a/test/message/util-inspect-error-cause.out +++ b/test/message/util-inspect-error-cause.out @@ -5,6 +5,7 @@ Error: Number error cause at * at * at * + at * at * { [cause]: 42 } @@ -15,6 +16,7 @@ Error: Object cause at * at * at * + at * at * { [cause]: { message: 'Unique', @@ -30,6 +32,7 @@ Error: undefined cause at * at * at * + at * at * { [cause]: undefined } @@ -40,6 +43,7 @@ Error: cause that throws at * at * at * + at * at * { [cause]: [Getter] } @@ -49,7 +53,7 @@ RangeError: New Stack Frames [cause]: FoobarError: Individual message at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { status: *[32m'Feeling good'*[39m, extraProperties: *[32m'Yes!'*[39m, @@ -61,17 +65,18 @@ RangeError: New Stack Frames *[90m at *[39m *[90m at *[39m *[90m at *[39m + *[90m at *[39m } } Error: Stack causes at * *[90m at *[39m -*[90m ... 4 lines matching cause stack trace ...*[39m +*[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { [cause]: FoobarError: Individual message at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { status: *[32m'Feeling good'*[39m, extraProperties: *[32m'Yes!'*[39m, @@ -83,6 +88,7 @@ Error: Stack causes *[90m at *[39m *[90m at *[39m *[90m at *[39m + *[90m at *[39m } } RangeError: New Stack Frames @@ -91,12 +97,12 @@ RangeError: New Stack Frames [cause]: Error: Stack causes at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { [cause]: FoobarError: Individual message at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { status: *[32m'Feeling good'*[39m, extraProperties: *[32m'Yes!'*[39m, @@ -108,6 +114,7 @@ RangeError: New Stack Frames *[90m at *[39m *[90m at *[39m *[90m at *[39m + *[90m at *[39m } } } @@ -117,7 +124,7 @@ RangeError: New Stack Frames [cause]: FoobarError: Individual message at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { status: 'Feeling good', extraProperties: 'Yes!', @@ -129,17 +136,18 @@ RangeError: New Stack Frames at * at * at * + at * } } Error: Stack causes at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { [cause]: FoobarError: Individual message at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * status: 'Feeling good', extraProperties: 'Yes!', @@ -151,6 +159,7 @@ Error: Stack causes at * at * at * + at * } } RangeError: New Stack Frames @@ -159,12 +168,12 @@ RangeError: New Stack Frames [cause]: Error: Stack causes at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { [cause]: FoobarError: Individual message at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { status: 'Feeling good', extraProperties: 'Yes!', @@ -176,6 +185,7 @@ RangeError: New Stack Frames at * at * at * + at * } } } diff --git a/test/message/util_inspect_error.out b/test/message/util_inspect_error.out index 644ccd58831ef7..31b65eb2e2bf3c 100644 --- a/test/message/util_inspect_error.out +++ b/test/message/util_inspect_error.out @@ -8,6 +8,7 @@ at * at * at * + at * nested: { err: Error: foo @@ -19,6 +20,7 @@ at * at * at * + at * { err: Error: foo bar @@ -29,6 +31,7 @@ at * at * at * + at * nested: { err: Error: foo bar @@ -39,6 +42,7 @@ at * at * at * + at * } } { Error: foo @@ -50,4 +54,5 @@ bar at * at * at * + at * foo: 'bar' } diff --git a/test/parallel/test-repl.js b/test/parallel/test-repl.js index 0d467e2b35dbdc..7f757837f7bdae 100644 --- a/test/parallel/test-repl.js +++ b/test/parallel/test-repl.js @@ -581,6 +581,7 @@ const errorTests = [ /^ {4}at .*/, /^ {4}at .*/, /^ {4}at .*/, + /^ {4}at .*/, " code: 'MODULE_NOT_FOUND',", " requireStack: [ '' ]", '}', diff --git a/test/pseudo-tty/console_colors.out b/test/pseudo-tty/console_colors.out index 006eb9edfe617d..80b147197431fa 100644 --- a/test/pseudo-tty/console_colors.out +++ b/test/pseudo-tty/console_colors.out @@ -12,6 +12,7 @@ foobar [90m at *[39m [90m at *[39m [90m at *[39m +[90m at *[39m Error: Should not ever get here. at Object. [90m(*node_modules*[4m*node_modules*[24m*bar.js:*:*[90m)[39m @@ -21,8 +22,8 @@ Error: Should not ever get here. [90m at *[39m [90m at *[39m [90m at *[39m - at Object. [90m(*console_colors.js:*:*[90m)[39m [90m at *[39m + at Object. [90m(*console_colors.js:*:*[90m)[39m [90m at *[39m Error diff --git a/test/pseudo-tty/test-fatal-error.out b/test/pseudo-tty/test-fatal-error.out index 3fe1eed39a021e..7040eb812ce6a8 100644 --- a/test/pseudo-tty/test-fatal-error.out +++ b/test/pseudo-tty/test-fatal-error.out @@ -8,6 +8,7 @@ TypeError: foobar [90m at *(node:internal*loader:*:*)[39m [90m at *(node:internal*loader:*:*)[39m [90m at *(node:internal*loader:*:*)[39m +[90m at *(node:internal*loader:*:*)[39m [90m at *[39m [90m at *[39m { bla: [33mtrue[39m diff --git a/test/pseudo-tty/test-trace-sigint.out b/test/pseudo-tty/test-trace-sigint.out index 956cbafccc2d19..ae6063b74242e4 100644 --- a/test/pseudo-tty/test-trace-sigint.out +++ b/test/pseudo-tty/test-trace-sigint.out @@ -7,3 +7,4 @@ KEYBOARD_INTERRUPT: Script execution was interrupted by `SIGINT` at * at * at * + at * From b607a1da34ed290b8735622349ff8394c81ff9a6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 20:56:45 -0300 Subject: [PATCH 18/29] escape backslash when is label --- lib/internal/util/debuglog.js | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index feb690c8f40ff1..f7864128e5f44e 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -171,6 +171,10 @@ function formatTime(ms) { return `${Number(NumberPrototypeToFixed(ms, 3))}ms`; } +function safeTraceLabel(label) { + return label.replace(/\\/g, '\\\\'); +} + /** * @typedef {(label: string, timeFormatted: string, args?: any[]) => void} LogImpl */ @@ -228,6 +232,7 @@ function time(timesStore, traceCategory, implementation, timerFlags, logLabel = } if ((timerFlags & kSkipTrace) === 0) { + traceLabel = safeTraceLabel(traceLabel); trace(kTraceBegin, traceCategory, traceLabel, 0); } @@ -266,8 +271,10 @@ function timeEnd( timeLogImpl(timesStore, implementation, logImpl, logLabel); } - if ((timerFlags & kSkipTrace) === 0) + if ((timerFlags & kSkipTrace) === 0) { + traceLabel = safeTraceLabel(traceLabel); trace(kTraceEnd, traceCategory, traceLabel, 0); + } timesStore.delete(logLabel); } @@ -307,6 +314,7 @@ function timeLog( } if ((timerFlags & kSkipTrace) === 0) { + traceLabel = safeTraceLabel(traceLabel); trace(kTraceInstant, traceCategory, traceLabel, 0); } } From ad790be5df1987376079848c2211ca74cd747e30 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 21:27:39 -0300 Subject: [PATCH 19/29] fix references for _load --- lib/internal/main/repl.js | 3 +-- lib/internal/modules/cjs/loader.js | 7 ++++++- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/lib/internal/main/repl.js b/lib/internal/main/repl.js index f7aa3a3e2602fa..823040321262f6 100644 --- a/lib/internal/main/repl.js +++ b/lib/internal/main/repl.js @@ -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')) { diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index f7093f0f92ec39..2f34b8605b9760 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -1293,7 +1293,12 @@ Module.prototype.require = function(id) { throw new ERR_INVALID_ARG_VALUE('id', id, 'must be a non-empty string'); } - return wrapModuleLoad(id, this, /** isMain */ false); + requireDepth++; + try { + return wrapModuleLoad(id, this, /* isMain */ false); + } finally { + requireDepth--; + } }; /** From 1c727c03dc291870b6885b19495d5db4d750dd44 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 21:28:01 -0300 Subject: [PATCH 20/29] add test to check against un-escaped backslash --- test/parallel/test-trace-events-console.js | 3 +++ 1 file changed, 3 insertions(+) diff --git a/test/parallel/test-trace-events-console.js b/test/parallel/test-trace-events-console.js index 4c9fa35cbafd6f..79ac37fc7d6570 100644 --- a/test/parallel/test-trace-events-console.js +++ b/test/parallel/test-trace-events-console.js @@ -10,6 +10,7 @@ const tmpdir = require('../common/tmpdir'); const names = [ 'time::foo', + 'time::\\winvalid_char', 'count::bar', ]; const expectedCounts = [ 1, 2, 0 ]; @@ -21,8 +22,10 @@ if (process.argv[2] === 'child') { console.count('bar'); console.count('bar'); console.countReset('bar'); + console.time('\\winvalid_char'); console.time('foo'); setImmediate(() => { + console.timeEnd('\\winvalid_char'); console.timeLog('foo'); setImmediate(() => { console.timeEnd('foo'); From fffaaae755e551ef863c9c7688e051d5891f3f94 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 22:10:43 -0300 Subject: [PATCH 21/29] fix issues with test & missing fn --- lib/internal/console/constructor.js | 6 ++++++ .../errors/unhandled_promise_trace_warnings.snapshot | 1 + 2 files changed, 7 insertions(+) diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 9e400e8e4f2263..c3488d40593acf 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -623,6 +623,12 @@ const iterKey = '(iteration index)'; const isArray = (v) => ArrayIsArray(v) || isTypedArray(v) || isBuffer(v); +// TODO: remove string type check once the styleText supports objects +// Return true if all args are type string +const shouldColorize = (args) => { + return lazyUtilColors().hasColors && !ArrayPrototypeSome(args, (arg) => typeof arg !== 'string'); +}; + function noop() {} for (const method of ReflectOwnKeys(consoleMethods)) diff --git a/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot b/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot index c95df6d5aa056d..94c709b17788c4 100644 --- a/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot +++ b/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot @@ -10,6 +10,7 @@ at * at * at * + at * (node:*) Error: This was rejected at * at * From 0ad8a70e471caa00eb9ffbdde3c2f8889423da1a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 22 May 2024 22:20:18 -0300 Subject: [PATCH 22/29] making eslint happy with trailing space --- lib/internal/util/debuglog.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index f7864128e5f44e..9daa65bcf548e5 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -232,7 +232,7 @@ function time(timesStore, traceCategory, implementation, timerFlags, logLabel = } if ((timerFlags & kSkipTrace) === 0) { - traceLabel = safeTraceLabel(traceLabel); + traceLabel = safeTraceLabel(traceLabel); trace(kTraceBegin, traceCategory, traceLabel, 0); } From d7ecab3427b7c9533d89d0d4571f72825fe36909 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Fri, 24 May 2024 19:11:38 -0300 Subject: [PATCH 23/29] minor changes --- lib/internal/modules/cjs/loader.js | 5 ++--- lib/internal/util/debuglog.js | 2 +- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 2f34b8605b9760..2c8584d2e1036e 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -184,7 +184,7 @@ const { const { debuglog, debugWithTimer } = require('internal/util/debuglog'); -let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => { +let { startTimer, endTimer } = debugWithTimer('module_timer', (start, end) => { startTimer = start; endTimer = end; }); @@ -198,8 +198,7 @@ let isPreloading = false; let statCache = null; /** - * Internal method to be able to add recursion & tracing capabilities - * for Module._load. + * Internal method to add tracing capabilities for Module._load. * * See more {@link Module._load} */ diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 9daa65bcf548e5..e4a283d9faa767 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -372,7 +372,7 @@ function debugWithTimer(set, cb) { ); } - const kTraceCategory = `node,node.debuglog_${StringPrototypeToLowerCase(set)}`; + const kTraceCategory = `node,node.${StringPrototypeToLowerCase(set)}`; let debugLogCategoryEnabled = false; let traceCategoryEnabled = false; let timerFlags = kNone; From 02b11b83cee7f47c3c1f13c316cfa6ed50c1d219 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Fri, 24 May 2024 21:38:12 -0300 Subject: [PATCH 24/29] fix missing changing the name of the module --- test/parallel/test-module-print-timing.mjs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 516a37e2567e73..afff6122b4402e 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -10,7 +10,7 @@ tmpdir.refresh(); it('should print the timing information for cjs', async () => { const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], { env: { - NODE_DEBUG: 'module_cjs', + NODE_DEBUG: 'module_timer', }, }); @@ -21,7 +21,7 @@ it('should print the timing information for cjs', async () => { const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); assert.notStrictEqual(firstLine, undefined); - assert.ok(firstLine.includes('MODULE_CJS'), `Not found MODULE_CJS on ${firstLine}`); + assert.ok(firstLine.includes('MODULE_TIMER'), `Not found MODULE_TIMER on ${firstLine}`); assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); }); @@ -30,7 +30,7 @@ it('should write tracing information for cjs', async () => { const outputFile = tmpdir.resolve('output-trace.log'); const result = await spawnPromisified(execPath, [ '--trace-event-categories', - 'node.debuglog_module_cjs', + 'node.module_timer', '--trace-event-file-pattern', outputFile, '--eval', @@ -58,14 +58,14 @@ it('should write tracing & print logs for cjs', async () => { const outputFile = tmpdir.resolve('output-trace-and-log.log'); const result = await spawnPromisified(execPath, [ '--trace-event-categories', - 'node.debuglog_module_cjs', + 'node.module_timer', '--trace-event-file-pattern', outputFile, '--eval', 'require("url");', ], { env: { - NODE_DEBUG: 'module_cjs', + NODE_DEBUG: 'module_timer', }, }); @@ -76,7 +76,7 @@ it('should write tracing & print logs for cjs', async () => { const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); assert.notStrictEqual(firstLine, undefined); - assert.ok(firstLine.includes('MODULE_CJS'), `Not found MODULE_CJS on ${firstLine}`); + assert.ok(firstLine.includes('MODULE_TIMER'), `Not found MODULE_TIMER on ${firstLine}`); assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); From 3d230330032ab65359a750268e0d6dbe137d8214 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 28 May 2024 21:36:05 -0300 Subject: [PATCH 25/29] try get more info from ci --- test/parallel/test-module-print-timing.mjs | 38 ++++++++++------------ 1 file changed, 18 insertions(+), 20 deletions(-) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index afff6122b4402e..797d2c1fa396bf 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -1,23 +1,22 @@ -import { spawnPromisified } from '../common/index.mjs'; -import tmpdir from '../common/tmpdir.js'; import assert from 'node:assert'; import { readFile } from 'node:fs/promises'; import { execPath } from 'node:process'; import { it } from 'node:test'; +import tmpdir from '../common/tmpdir.js'; +import { spawnSyncAndAssert } from '../common/child_process.js'; tmpdir.refresh(); -it('should print the timing information for cjs', async () => { - const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], { +it('should print the timing information for cjs', () => { + const result = spawnSyncAndAssert(execPath, ['--eval', 'require("url");'], { env: { NODE_DEBUG: 'module_timer', }, + }, { + stdout: '', + stderr: result => result.includes('MODULE_TIMER'), }); - 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); @@ -28,19 +27,18 @@ it('should print the timing information for cjs', async () => { it('should write tracing information for cjs', async () => { const outputFile = tmpdir.resolve('output-trace.log'); - const result = await spawnPromisified(execPath, [ + + spawnSyncAndAssert(execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', outputFile, '--eval', 'require("url");', - ]); - - assert.strictEqual(result.code, 0); - assert.strictEqual(result.signal, null); - assert.strictEqual(result.stdout, ''); - assert.strictEqual(result.stderr, ''); + ], { + stdout: '', + stderr: '', + }); const expectedMimeTypes = ['b', 'e']; const outputFileContent = await readFile(outputFile, 'utf-8'); @@ -56,7 +54,8 @@ it('should write tracing information for cjs', async () => { it('should write tracing & print logs for cjs', async () => { const outputFile = tmpdir.resolve('output-trace-and-log.log'); - const result = await spawnPromisified(execPath, [ + + const result = spawnSyncAndAssert(execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', @@ -67,12 +66,11 @@ it('should write tracing & print logs for cjs', async () => { env: { NODE_DEBUG: 'module_timer', }, + }, { + stdout: '', + stderr: result => result.includes('MODULE_TIMER'), }); - 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); From 455d40832120f4b5d6c7f371ac87d4586fb7f55f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 28 May 2024 21:42:46 -0300 Subject: [PATCH 26/29] try get more info from ci & make lint happy --- test/parallel/test-module-print-timing.mjs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 797d2c1fa396bf..456a495beb920a 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -1,20 +1,20 @@ +import * as common from '../common/index.mjs'; import assert from 'node:assert'; import { readFile } from 'node:fs/promises'; import { execPath } from 'node:process'; import { it } from 'node:test'; import tmpdir from '../common/tmpdir.js'; -import { spawnSyncAndAssert } from '../common/child_process.js'; tmpdir.refresh(); it('should print the timing information for cjs', () => { - const result = spawnSyncAndAssert(execPath, ['--eval', 'require("url");'], { + const result = common.spawnSyncAndAssert(execPath, ['--eval', 'require("url");'], { env: { NODE_DEBUG: 'module_timer', }, }, { stdout: '', - stderr: result => result.includes('MODULE_TIMER'), + stderr: (result) => result.includes('MODULE_TIMER'), }); const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); @@ -28,7 +28,7 @@ it('should print the timing information for cjs', () => { it('should write tracing information for cjs', async () => { const outputFile = tmpdir.resolve('output-trace.log'); - spawnSyncAndAssert(execPath, [ + common.spawnSyncAndAssert(execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', @@ -55,7 +55,7 @@ it('should write tracing information for cjs', async () => { it('should write tracing & print logs for cjs', async () => { const outputFile = tmpdir.resolve('output-trace-and-log.log'); - const result = spawnSyncAndAssert(execPath, [ + const result = common.spawnSyncAndAssert(execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', @@ -68,7 +68,7 @@ it('should write tracing & print logs for cjs', async () => { }, }, { stdout: '', - stderr: result => result.includes('MODULE_TIMER'), + stderr: (result) => result.includes('MODULE_TIMER'), }); const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); From 2f3a1020c8f42ea7bf75c362cae3f8133ccd999a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 28 May 2024 22:05:40 -0300 Subject: [PATCH 27/29] fix import of common and spawnSync --- test/parallel/test-module-print-timing.mjs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 456a495beb920a..2bf5bb9f1ade25 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -1,14 +1,15 @@ -import * as common from '../common/index.mjs'; +import '../common/index.mjs'; import assert from 'node:assert'; import { readFile } from 'node:fs/promises'; import { execPath } from 'node:process'; import { it } from 'node:test'; import tmpdir from '../common/tmpdir.js'; +import { spawnSyncAndAssert } from '../common/child_process.js'; tmpdir.refresh(); it('should print the timing information for cjs', () => { - const result = common.spawnSyncAndAssert(execPath, ['--eval', 'require("url");'], { + const result = spawnSyncAndAssert(execPath, ['--eval', 'require("url");'], { env: { NODE_DEBUG: 'module_timer', }, @@ -28,7 +29,7 @@ it('should print the timing information for cjs', () => { it('should write tracing information for cjs', async () => { const outputFile = tmpdir.resolve('output-trace.log'); - common.spawnSyncAndAssert(execPath, [ + spawnSyncAndAssert(execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', @@ -55,7 +56,7 @@ it('should write tracing information for cjs', async () => { it('should write tracing & print logs for cjs', async () => { const outputFile = tmpdir.resolve('output-trace-and-log.log'); - const result = common.spawnSyncAndAssert(execPath, [ + const result = spawnSyncAndAssert(execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', From 51d1a39121379849d48cbf1b018c8a0127c5064c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Tue, 28 May 2024 22:35:47 -0300 Subject: [PATCH 28/29] do not cache process.execPath on import --- test/parallel/test-module-print-timing.mjs | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 2bf5bb9f1ade25..032bd792cc8982 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -1,7 +1,6 @@ import '../common/index.mjs'; import assert from 'node:assert'; import { readFile } from 'node:fs/promises'; -import { execPath } from 'node:process'; import { it } from 'node:test'; import tmpdir from '../common/tmpdir.js'; import { spawnSyncAndAssert } from '../common/child_process.js'; @@ -9,7 +8,8 @@ import { spawnSyncAndAssert } from '../common/child_process.js'; tmpdir.refresh(); it('should print the timing information for cjs', () => { - const result = spawnSyncAndAssert(execPath, ['--eval', 'require("url");'], { + const result = spawnSyncAndAssert(process.execPath, ['--eval', 'require("url");'], { + cwd: tmpdir.path, env: { NODE_DEBUG: 'module_timer', }, @@ -29,7 +29,7 @@ it('should print the timing information for cjs', () => { it('should write tracing information for cjs', async () => { const outputFile = tmpdir.resolve('output-trace.log'); - spawnSyncAndAssert(execPath, [ + spawnSyncAndAssert(process.execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', @@ -37,6 +37,8 @@ it('should write tracing information for cjs', async () => { '--eval', 'require("url");', ], { + cwd: tmpdir.path, + }, { stdout: '', stderr: '', }); @@ -56,7 +58,7 @@ it('should write tracing information for cjs', async () => { it('should write tracing & print logs for cjs', async () => { const outputFile = tmpdir.resolve('output-trace-and-log.log'); - const result = spawnSyncAndAssert(execPath, [ + const result = spawnSyncAndAssert(process.execPath, [ '--trace-event-categories', 'node.module_timer', '--trace-event-file-pattern', @@ -64,6 +66,7 @@ it('should write tracing & print logs for cjs', async () => { '--eval', 'require("url");', ], { + cwd: tmpdir.path, env: { NODE_DEBUG: 'module_timer', }, From 5adcb8ad60e37cd14bebb9c6e0a82d0b98f14391 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Louren=C3=A7o?= Date: Wed, 29 May 2024 08:33:49 -0300 Subject: [PATCH 29/29] thanks richard, you are amazing --- test/parallel/test-module-print-timing.mjs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs index 032bd792cc8982..0cb7189d3114af 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -11,6 +11,7 @@ it('should print the timing information for cjs', () => { const result = spawnSyncAndAssert(process.execPath, ['--eval', 'require("url");'], { cwd: tmpdir.path, env: { + ...process.env, NODE_DEBUG: 'module_timer', }, }, { @@ -68,6 +69,7 @@ it('should write tracing & print logs for cjs', async () => { ], { cwd: tmpdir.path, env: { + ...process.env, NODE_DEBUG: 'module_timer', }, }, {