Skip to content

Commit

Permalink
add trace label to better visualization
Browse files Browse the repository at this point in the history
  • Loading branch information
@H4ad
H4ad committed Mar 30, 2024
1 parent 3f11f08 commit 2cbc79a
Show file tree
Hide file tree
Showing 4 changed files with 68 additions and 45 deletions.
6 changes: 3 additions & 3 deletions lib/internal/console/constructor.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -393,21 +393,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) {
Expand Down
19 changes: 10 additions & 9 deletions lib/internal/modules/cjs/loader.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -977,9 +977,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) {
Expand All @@ -997,12 +998,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];
Expand All @@ -1019,7 +1020,7 @@ Module._load = function(request, parent, isMain) {

const module = loadBuiltinModule(id, request);

endTimer(label);
endTimer(logLabel, traceLabel);
return module.exports;
}

Expand All @@ -1032,21 +1033,21 @@ Module._load = function(request, parent, isMain) {
if (!parseCachedModule || parseCachedModule.loaded) {
const result = getExportsForCircularRequire(cachedModule);

endTimer(label);
endTimer(logLabel, traceLabel);

return result;
}
parseCachedModule.loaded = true;
} else {
endTimer(label);
endTimer(logLabel, traceLabel);
return cachedModule.exports;
}
}

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

endTimer(label);
endTimer(logLabel, traceLabel);

return mod.exports;
}
Expand Down Expand Up @@ -1095,7 +1096,7 @@ Module._load = function(request, parent, isMain) {
}
}

endTimer(label);
endTimer(logLabel, traceLabel);

return module.exports;
};
Expand Down
30 changes: 15 additions & 15 deletions lib/internal/util/debuglog.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
*/

/**
Expand Down Expand Up @@ -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() {
Expand All @@ -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 {
Expand Down
58 changes: 40 additions & 18 deletions lib/internal/util/trace_timer.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -95,38 +95,52 @@ 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());
}

/**
* @param {SafeMap} timesStore
* @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);
}
}

Expand All @@ -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) {

Check failure on line 157 in lib/internal/util/trace_timer.js

View workflow job for this annotation

GitHub Actions / lint-js-and-md 

This line has a length of 122. Maximum allowed is 120
// 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 = {
Expand Down

0 comments on commit 2cbc79a

Please sign in to comment.