Skip to content

Commit d7b53fb

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

File tree

7 files changed

+357
-119
lines changed

7 files changed

+357
-119
lines changed

‎lib/internal/console/constructor.js

+34-95
Original file line numberDiff line numberDiff line change
@@ -68,12 +68,10 @@ const {
6868
CHAR_UPPERCASE_C: kTraceCount,
6969
} = require('internal/constants');
7070
const kCounts = Symbol('counts');
71+
const { time, timeEnd, timeLog } = require('internal/util/trace_timer');
7172

7273
const kTraceConsoleCategory = 'node,node.console';
7374

74-
const kSecond = 1000;
75-
const kMinute = 60 * kSecond;
76-
const kHour = 60 * kMinute;
7775
const kMaxGroupIndentation = 1000;
7876

7977
// Lazy loaded for startup performance.
@@ -99,6 +97,7 @@ const kBindStreamsEager = Symbol('kBindStreamsEager');
9997
const kBindStreamsLazy = Symbol('kBindStreamsLazy');
10098
const kUseStdout = Symbol('kUseStdout');
10199
const kUseStderr = Symbol('kUseStderr');
100+
const kInternalTimeLogImpl = Symbol('kInternalTimeLogImpl');
102101

103102
const optionsMap = new SafeWeakMap();
104103
function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
@@ -138,14 +137,14 @@ function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
138137

139138
if (groupIndentation !== undefined) {
140139
validateInteger(groupIndentation, 'groupIndentation',
141-
0, kMaxGroupIndentation);
140+
0, kMaxGroupIndentation);
142141
}
143142

144143
if (inspectOptions !== undefined) {
145144
validateObject(inspectOptions, 'options.inspectOptions');
146145

147146
if (inspectOptions.colors !== undefined &&
148-
options.colorMode !== undefined) {
147+
options.colorMode !== undefined) {
149148
throw new ERR_INCOMPATIBLE_OPTION_PAIR(
150149
'options.inspectOptions.color', 'colorMode');
151150
}
@@ -190,7 +189,7 @@ ObjectDefineProperties(Console.prototype, {
190189
__proto__: null,
191190
...consolePropAttributes,
192191
// Eager version for the Console constructor
193-
value: function(stdout, stderr) {
192+
value: function (stdout, stderr) {
194193
ObjectDefineProperties(this, {
195194
'_stdout': { __proto__: null, ...consolePropAttributes, value: stdout },
196195
'_stderr': { __proto__: null, ...consolePropAttributes, value: stderr },
@@ -202,7 +201,7 @@ ObjectDefineProperties(Console.prototype, {
202201
...consolePropAttributes,
203202
// Lazily load the stdout and stderr from an object so we don't
204203
// create the stdio streams when they are not even accessed
205-
value: function(object) {
204+
value: function (object) {
206205
let stdout;
207206
let stderr;
208207
ObjectDefineProperties(this, {
@@ -232,7 +231,7 @@ ObjectDefineProperties(Console.prototype, {
232231
[kBindProperties]: {
233232
__proto__: null,
234233
...consolePropAttributes,
235-
value: function(ignoreErrors, colorMode, groupIndentation = 2) {
234+
value: function (ignoreErrors, colorMode, groupIndentation = 2) {
236235
ObjectDefineProperties(this, {
237236
'_stdoutErrorHandler': {
238237
__proto__: null,
@@ -273,7 +272,7 @@ ObjectDefineProperties(Console.prototype, {
273272
[kWriteToConsole]: {
274273
__proto__: null,
275274
...consolePropAttributes,
276-
value: function(streamSymbol, string) {
275+
value: function (streamSymbol, string) {
277276
const ignoreErrors = this._ignoreErrors;
278277
const groupIndent = this[kGroupIndent];
279278

@@ -316,7 +315,7 @@ ObjectDefineProperties(Console.prototype, {
316315
[kGetInspectOptions]: {
317316
__proto__: null,
318317
...consolePropAttributes,
319-
value: function(stream) {
318+
value: function (stream) {
320319
let color = this[kColorMode];
321320
if (color === 'auto') {
322321
color = lazyUtilColors().shouldColorize(stream);
@@ -336,7 +335,7 @@ ObjectDefineProperties(Console.prototype, {
336335
[kFormatForStdout]: {
337336
__proto__: null,
338337
...consolePropAttributes,
339-
value: function(args) {
338+
value: function (args) {
340339
const opts = this[kGetInspectOptions](this._stdout);
341340
ArrayPrototypeUnshift(args, opts);
342341
return ReflectApply(formatWithOptions, null, args);
@@ -345,7 +344,7 @@ ObjectDefineProperties(Console.prototype, {
345344
[kFormatForStderr]: {
346345
__proto__: null,
347346
...consolePropAttributes,
348-
value: function(args) {
347+
value: function (args) {
349348
const opts = this[kGetInspectOptions](this._stderr);
350349
ArrayPrototypeUnshift(args, opts);
351350
return ReflectApply(formatWithOptions, null, args);
@@ -374,6 +373,14 @@ function createWriteErrorHandler(instance, streamSymbol) {
374373
};
375374
}
376375

376+
function timeLogImpl(label, formatted, args) {
377+
if (args === undefined) {
378+
this.log('%s: %s', label, formatted);
379+
} else {
380+
this.log('%s: %s', label, formatted, ...new SafeArrayIterator(args));
381+
}
382+
}
383+
377384
const consoleMethods = {
378385
log(...args) {
379386
this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args));
@@ -394,31 +401,21 @@ const consoleMethods = {
394401
},
395402

396403
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());
404+
time(this._times, kTraceConsoleCategory, 'console.time()', label);
405405
},
406406

407407
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-
}
408+
if (this[kInternalTimeLogImpl] === undefined)
409+
this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this)
410+
411+
timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', this[kInternalTimeLogImpl], label);
415412
},
416413

417414
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);
415+
if (this[kInternalTimeLogImpl] === undefined)
416+
this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this)
417+
418+
timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', this[kInternalTimeLogImpl], label, data);
422419
},
423420

424421
trace: function trace(...args) {
@@ -515,9 +512,9 @@ const consoleMethods = {
515512

516513
const _inspect = (v) => {
517514
const depth = v !== null &&
518-
typeof v === 'object' &&
519-
!isArray(v) &&
520-
ObjectKeys(v).length > 2 ? -1 : 0;
515+
typeof v === 'object' &&
516+
!isArray(v) &&
517+
ObjectKeys(v).length > 2 ? -1 : 0;
521518
const opt = {
522519
depth,
523520
maxArrayLength: 3,
@@ -587,7 +584,7 @@ const consoleMethods = {
587584
for (; i < indexKeyArray.length; i++) {
588585
const item = tabularData[indexKeyArray[i]];
589586
const primitive = item === null ||
590-
(typeof item !== 'function' && typeof item !== 'object');
587+
(typeof item !== 'function' && typeof item !== 'object');
591588
if (properties === undefined && primitive) {
592589
hasPrimitives = true;
593590
valuesKeyArray[i] = _inspect(item);
@@ -596,7 +593,7 @@ const consoleMethods = {
596593
for (const key of keys) {
597594
map[key] ??= [];
598595
if ((primitive && properties) ||
599-
!ObjectPrototypeHasOwnProperty(item, key))
596+
!ObjectPrototypeHasOwnProperty(item, key))
600597
map[key][i] = '';
601598
else
602599
map[key][i] = _inspect(item[key]);
@@ -617,71 +614,14 @@ const consoleMethods = {
617614
},
618615
};
619616

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-
677617
const keyKey = 'Key';
678618
const valuesKey = 'Values';
679619
const indexKey = '(index)';
680620
const iterKey = '(iteration index)';
681621

682622
const isArray = (v) => ArrayIsArray(v) || isTypedArray(v) || isBuffer(v);
683623

684-
function noop() {}
624+
function noop() { }
685625

686626
for (const method of ReflectOwnKeys(consoleMethods))
687627
Console.prototype[method] = consoleMethods[method];
@@ -728,5 +668,4 @@ module.exports = {
728668
kBindStreamsLazy,
729669
kBindProperties,
730670
initializeGlobalConsole,
731-
formatTime, // exported for tests
732671
};

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

+14-15
Original file line numberDiff line numberDiff line change
@@ -360,7 +360,7 @@ function setModuleParent(value) {
360360
moduleParentCache.set(this, value);
361361
}
362362

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

365365
let debug = debuglog('module', (fn) => {
366366
debug = fn;
@@ -372,8 +372,9 @@ let hrtimeBigIntTimingFn = () => {
372372
return hrtimeBigIntTimingFn();
373373
};
374374

375-
let debugTiming = debuglog('timing_module_cjs', (fn) => {
376-
debugTiming = fn;
375+
let { startTimer, endTimer } = debugWithTimer('module_cjs', (start, end) => {
376+
startTimer = start;
377+
endTimer = end;
377378
});
378379

379380
ObjectDefineProperty(Module.prototype, 'parent', {
@@ -971,10 +972,6 @@ function getExportsForCircularRequire(module) {
971972
return module.exports;
972973
}
973974

974-
function logTiming(request, parent, start) {
975-
debugTiming('[%s] [%s]: %d ms', parent?.id || '', request, Number((hrtimeBigIntTimingFn() - start)) / 1e6);
976-
}
977-
978975
/**
979976
* Load a module from cache if it exists, otherwise create a new module instance.
980977
* 1. If a module already exists in the cache: return its exports object.
@@ -987,7 +984,9 @@ function logTiming(request, parent, start) {
987984
* @param {boolean} isMain Whether the module is the main entry point
988985
*/
989986
Module._load = function(request, parent, isMain) {
990-
const start = hrtimeBigIntTimingFn();
987+
const label = `[${parent?.id || ''}] [${request}]`;
988+
989+
startTimer(label);
991990

992991
let relResolveCacheIdentifier;
993992
if (parent) {
@@ -1005,12 +1004,12 @@ Module._load = function(request, parent, isMain) {
10051004
if (!cachedModule.loaded) {
10061005
const result = getExportsForCircularRequire(cachedModule);
10071006

1008-
logTiming(request, parent, start);
1007+
endTimer(label);
10091008

10101009
return result;
10111010
}
10121011

1013-
logTiming(request, parent, start);
1012+
endTimer(label);
10141013
return cachedModule.exports;
10151014
}
10161015
delete relativeResolveCache[relResolveCacheIdentifier];
@@ -1027,7 +1026,7 @@ Module._load = function(request, parent, isMain) {
10271026

10281027
const module = loadBuiltinModule(id, request);
10291028

1030-
logTiming(request, parent, start);
1029+
endTimer(label);
10311030
return module.exports;
10321031
}
10331032

@@ -1040,21 +1039,21 @@ Module._load = function(request, parent, isMain) {
10401039
if (!parseCachedModule || parseCachedModule.loaded) {
10411040
const result = getExportsForCircularRequire(cachedModule);
10421041

1043-
logTiming(request, parent, start);
1042+
endTimer(label);
10441043

10451044
return result;
10461045
}
10471046
parseCachedModule.loaded = true;
10481047
} else {
1049-
logTiming(request, parent, start);
1048+
endTimer(label);
10501049
return cachedModule.exports;
10511050
}
10521051
}
10531052

10541053
if (BuiltinModule.canBeRequiredWithoutScheme(filename)) {
10551054
const mod = loadBuiltinModule(filename, request);
10561055

1057-
logTiming(request, parent, start);
1056+
endTimer(label);
10581057

10591058
return mod.exports;
10601059
}
@@ -1103,7 +1102,7 @@ Module._load = function(request, parent, isMain) {
11031102
}
11041103
}
11051104

1106-
logTiming(request, parent, start);
1105+
endTimer(label);
11071106

11081107
return module.exports;
11091108
};

0 commit comments

Comments
 (0)