diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 454652e3632472..6326cc734c5be3 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -12,9 +12,6 @@ const { Boolean, ErrorCaptureStackTrace, FunctionPrototypeBind, - MathFloor, - Number, - NumberPrototypeToFixed, ObjectDefineProperties, ObjectDefineProperty, ObjectKeys, @@ -29,10 +26,8 @@ const { SafeWeakMap, SafeSet, StringPrototypeIncludes, - StringPrototypePadStart, StringPrototypeRepeat, StringPrototypeSlice, - StringPrototypeSplit, Symbol, SymbolHasInstance, SymbolToStringTag, @@ -62,18 +57,13 @@ 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 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. @@ -99,6 +89,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 */) { @@ -145,7 +136,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'); } @@ -374,6 +365,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)); @@ -394,31 +393,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) { @@ -515,9 +504,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, @@ -587,7 +576,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); @@ -596,7 +585,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]); @@ -617,63 +606,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)'; @@ -681,7 +613,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]; @@ -728,5 +660,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 b31dc8e5657ade..6807acb1715ddb 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -61,7 +61,6 @@ const { StringPrototypeSplit, StringPrototypeStartsWith, Symbol, - Number, } = primordials; // Map used to store CJS parsing data or for ESM loading. @@ -360,20 +359,15 @@ function setModuleParent(value) { moduleParentCache.set(this, 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', { @@ -971,10 +965,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. @@ -987,7 +977,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) { @@ -1005,12 +997,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]; @@ -1027,7 +1019,7 @@ Module._load = function(request, parent, isMain) { const module = loadBuiltinModule(id, request); - logTiming(request, parent, start); + endTimer(label); return module.exports; } @@ -1040,13 +1032,13 @@ Module._load = function(request, parent, isMain) { if (!parseCachedModule || parseCachedModule.loaded) { const result = getExportsForCircularRequire(cachedModule); - logTiming(request, parent, start); + endTimer(label); return result; } parseCachedModule.loaded = true; } else { - logTiming(request, parent, start); + endTimer(label); return cachedModule.exports; } } @@ -1054,7 +1046,7 @@ Module._load = function(request, parent, isMain) { if (BuiltinModule.canBeRequiredWithoutScheme(filename)) { const mod = loadBuiltinModule(filename, request); - logTiming(request, parent, start); + endTimer(label); return mod.exports; } @@ -1103,7 +1095,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..5abe09fe4e0b23 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -5,11 +5,13 @@ 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'); // `debugImpls` and `testEnabled` are deliberately not initialized so any call // to `debuglog()` before `initializeDebugEnv()` is called will throw. @@ -43,7 +45,7 @@ function emitWarningIfNeeded(set) { } } -const noop = () => {}; +const noop = () => { }; let utilColors; function lazyUtilColors() { @@ -51,7 +53,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 +78,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 +137,143 @@ 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; + + /** + * @type {TimerStart} + */ + function internalStartTimer(label) { + time(tracesStores[set], kTraceCategory, 'debuglog.time', label); + } + + /** + * @type {TimerEnd} + */ + function internalEndTimer(label) { + timeEnd(tracesStores[set], kTraceCategory, 'debuglog.timeEnd', selectedLogImpl, label); + } + + /** + * @type {TimerLog} + */ + function internalLogTimer(label, args) { + timeLog(tracesStores[set], kTraceCategory, 'debuglog.timeLog', selectedLogImpl, label, args); + } + + function init() { + if (tracesStores[set] === undefined) { + tracesStores[set] = new SafeMap(); + } + emitWarningIfNeeded(set); + selectedLogImpl = testEnabled(set) ? 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..e414bca27721bc 100644 --- a/test/parallel/test-module-print-timing.mjs +++ b/test/parallel/test-module-print-timing.mjs @@ -4,10 +4,10 @@ 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'; + process.env.NODE_DEBUG = 'module_cjs'; const result = await spawnPromisified(execPath, ['--eval', 'require("url");'], { env: { - NODE_DEBUG: 'timing_module_cjs', + NODE_DEBUG: 'module_cjs', }, }); @@ -18,7 +18,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}`); });