Skip to content

Commit 45e5efa

Browse files
H4adH4ad
committed
try support both node_debug and trace by introducing a new module
1 parent ac6e394 commit 45e5efa

File tree

7 files changed

+358
-126
lines changed

7 files changed

+358
-126
lines changed

‎lib/internal/console/constructor.js

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

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

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

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

10394
const optionsMap = new SafeWeakMap();
10495
function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
@@ -145,7 +136,7 @@ function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
145136
validateObject(inspectOptions, 'options.inspectOptions');
146137

147138
if (inspectOptions.colors !== undefined &&
148-
options.colorMode !== undefined) {
139+
options.colorMode !== undefined) {
149140
throw new ERR_INCOMPATIBLE_OPTION_PAIR(
150141
'options.inspectOptions.color', 'colorMode');
151142
}
@@ -374,6 +365,14 @@ function createWriteErrorHandler(instance, streamSymbol) {
374365
};
375366
}
376367

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

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

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

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

424413
trace: function trace(...args) {
@@ -515,9 +504,9 @@ const consoleMethods = {
515504

516505
const _inspect = (v) => {
517506
const depth = v !== null &&
518-
typeof v === 'object' &&
519-
!isArray(v) &&
520-
ObjectKeys(v).length > 2 ? -1 : 0;
507+
typeof v === 'object' &&
508+
!isArray(v) &&
509+
ObjectKeys(v).length > 2 ? -1 : 0;
521510
const opt = {
522511
depth,
523512
maxArrayLength: 3,
@@ -587,7 +576,7 @@ const consoleMethods = {
587576
for (; i < indexKeyArray.length; i++) {
588577
const item = tabularData[indexKeyArray[i]];
589578
const primitive = item === null ||
590-
(typeof item !== 'function' && typeof item !== 'object');
579+
(typeof item !== 'function' && typeof item !== 'object');
591580
if (properties === undefined && primitive) {
592581
hasPrimitives = true;
593582
valuesKeyArray[i] = _inspect(item);
@@ -596,7 +585,7 @@ const consoleMethods = {
596585
for (const key of keys) {
597586
map[key] ??= [];
598587
if ((primitive && properties) ||
599-
!ObjectPrototypeHasOwnProperty(item, key))
588+
!ObjectPrototypeHasOwnProperty(item, key))
600589
map[key][i] = '';
601590
else
602591
map[key][i] = _inspect(item[key]);
@@ -617,71 +606,14 @@ const consoleMethods = {
617606
},
618607
};
619608

620-
// Returns true if label was found
621-
function timeLogImpl(self, name, label, data) {
622-
const time = self._times.get(label);
623-
if (time === undefined) {
624-
process.emitWarning(`No such label '${label}' for console.${name}()`);
625-
return false;
626-
}
627-
const duration = process.hrtime(time);
628-
const ms = duration[0] * 1000 + duration[1] / 1e6;
629-
630-
const formatted = formatTime(ms);
631-
632-
if (data === undefined) {
633-
self.log('%s: %s', label, formatted);
634-
} else {
635-
self.log('%s: %s', label, formatted, ...new SafeArrayIterator(data));
636-
}
637-
return true;
638-
}
639-
640-
function pad(value) {
641-
return StringPrototypePadStart(`${value}`, 2, '0');
642-
}
643-
644-
function formatTime(ms) {
645-
let hours = 0;
646-
let minutes = 0;
647-
let seconds = 0;
648-
649-
if (ms >= kSecond) {
650-
if (ms >= kMinute) {
651-
if (ms >= kHour) {
652-
hours = MathFloor(ms / kHour);
653-
ms = ms % kHour;
654-
}
655-
minutes = MathFloor(ms / kMinute);
656-
ms = ms % kMinute;
657-
}
658-
seconds = ms / kSecond;
659-
}
660-
661-
if (hours !== 0 || minutes !== 0) {
662-
({ 0: seconds, 1: ms } = StringPrototypeSplit(
663-
NumberPrototypeToFixed(seconds, 3),
664-
'.',
665-
));
666-
const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes;
667-
return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`;
668-
}
669-
670-
if (seconds !== 0) {
671-
return `${NumberPrototypeToFixed(seconds, 3)}s`;
672-
}
673-
674-
return `${Number(NumberPrototypeToFixed(ms, 3))}ms`;
675-
}
676-
677609
const keyKey = 'Key';
678610
const valuesKey = 'Values';
679611
const indexKey = '(index)';
680612
const iterKey = '(iteration index)';
681613

682614
const isArray = (v) => ArrayIsArray(v) || isTypedArray(v) || isBuffer(v);
683615

684-
function noop() {}
616+
function noop() { }
685617

686618
for (const method of ReflectOwnKeys(consoleMethods))
687619
Console.prototype[method] = consoleMethods[method];
@@ -728,5 +660,4 @@ module.exports = {
728660
kBindStreamsLazy,
729661
kBindProperties,
730662
initializeGlobalConsole,
731-
formatTime, // exported for tests
732663
};

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

+14-22
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,6 @@ const {
6161
StringPrototypeSplit,
6262
StringPrototypeStartsWith,
6363
Symbol,
64-
Number,
6564
} = primordials;
6665

6766
// Map used to store CJS parsing data or for ESM loading.
@@ -360,20 +359,15 @@ function setModuleParent(value) {
360359
moduleParentCache.set(this, value);
361360
}
362361

363-
const { debuglog, isDebugEnabled } = require('internal/util/debuglog');
362+
const { debuglog, debugWithTimer } = require('internal/util/debuglog');
364363

365364
let debug = debuglog('module', (fn) => {
366365
debug = fn;
367366
});
368367

369-
let hrtimeBigIntTimingFn = () => {
370-
hrtimeBigIntTimingFn = isDebugEnabled('timing_module_cjs') ? process.hrtime.bigint : () => 0;
371-
372-
return hrtimeBigIntTimingFn();
373-
};
374-
375-
let debugTiming = debuglog('timing_module_cjs', (fn) => {
376-
debugTiming = fn;
368+
let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => {
369+
startTimer = start;
370+
endTimer = end;
377371
});
378372

379373
ObjectDefineProperty(Module.prototype, 'parent', {
@@ -971,10 +965,6 @@ function getExportsForCircularRequire(module) {
971965
return module.exports;
972966
}
973967

974-
function logTiming(request, parent, start) {
975-
debugTiming('[%s] [%s]: %d ms', parent?.id || '', request, Number((hrtimeBigIntTimingFn() - start)) / 1e6);
976-
}
977-
978968
/**
979969
* Load a module from cache if it exists, otherwise create a new module instance.
980970
* 1. If a module already exists in the cache: return its exports object.
@@ -987,7 +977,9 @@ function logTiming(request, parent, start) {
987977
* @param {boolean} isMain Whether the module is the main entry point
988978
*/
989979
Module._load = function(request, parent, isMain) {
990-
const start = hrtimeBigIntTimingFn();
980+
const label = `[${parent?.id || ''}] [${request}]`;
981+
982+
startTimer(label);
991983

992984
let relResolveCacheIdentifier;
993985
if (parent) {
@@ -1005,12 +997,12 @@ Module._load = function(request, parent, isMain) {
1005997
if (!cachedModule.loaded) {
1006998
const result = getExportsForCircularRequire(cachedModule);
1007999

1008-
logTiming(request, parent, start);
1000+
endTimer(label);
10091001

10101002
return result;
10111003
}
10121004

1013-
logTiming(request, parent, start);
1005+
endTimer(label);
10141006
return cachedModule.exports;
10151007
}
10161008
delete relativeResolveCache[relResolveCacheIdentifier];
@@ -1027,7 +1019,7 @@ Module._load = function(request, parent, isMain) {
10271019

10281020
const module = loadBuiltinModule(id, request);
10291021

1030-
logTiming(request, parent, start);
1022+
endTimer(label);
10311023
return module.exports;
10321024
}
10331025

@@ -1040,21 +1032,21 @@ Module._load = function(request, parent, isMain) {
10401032
if (!parseCachedModule || parseCachedModule.loaded) {
10411033
const result = getExportsForCircularRequire(cachedModule);
10421034

1043-
logTiming(request, parent, start);
1035+
endTimer(label);
10441036

10451037
return result;
10461038
}
10471039
parseCachedModule.loaded = true;
10481040
} else {
1049-
logTiming(request, parent, start);
1041+
endTimer(label);
10501042
return cachedModule.exports;
10511043
}
10521044
}
10531045

10541046
if (BuiltinModule.canBeRequiredWithoutScheme(filename)) {
10551047
const mod = loadBuiltinModule(filename, request);
10561048

1057-
logTiming(request, parent, start);
1049+
endTimer(label);
10581050

10591051
return mod.exports;
10601052
}
@@ -1103,7 +1095,7 @@ Module._load = function(request, parent, isMain) {
11031095
}
11041096
}
11051097

1106-
logTiming(request, parent, start);
1098+
endTimer(label);
11071099

11081100
return module.exports;
11091101
};

0 commit comments

Comments
 (0)