Skip to content

lib: improve debuglog() performance #32260

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
mscdex merged 1 commit into from
May 30, 2020
Merged

lib: improve debuglog() performance #32260

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 3 additions & 1 deletion lib/_http_agent.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,9 @@ const {

const net = require('net');
const EventEmitter = require('events');
const debug = require('internal/util/debuglog').debuglog('http');
let debug = require('internal/util/debuglog').debuglog('http', (fn) => {
debug = fn;
});
const { async_id_symbol } = require('internal/async_hooks').symbols;
const {
codes: {
Expand Down
4 changes: 3 additions & 1 deletion lib/_http_common.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,9 @@ const {
readStop
} = incoming;

const debug = require('internal/util/debuglog').debuglog('http');
let debug = require('internal/util/debuglog').debuglog('http', (fn) => {
debug = fn;
});

const kIncomingMessage = Symbol('IncomingMessage');
const kOnHeaders = HTTPParser.kOnHeaders | 0;
Expand Down
4 changes: 3 additions & 1 deletion lib/_stream_readable.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,9 @@ const EE = require('events');
const Stream = require('stream');
const { Buffer } = require('buffer');

const debug = require('internal/util/debuglog').debuglog('stream');
let debug = require('internal/util/debuglog').debuglog('stream', (fn) => {
debug = fn;
});
const BufferList = require('internal/streams/buffer_list');
const destroyImpl = require('internal/streams/destroy');
const {
Expand Down
4 changes: 3 additions & 1 deletion lib/_tls_wrap.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,9 @@ const tls = require('tls');
const common = require('_tls_common');
const JSStreamSocket = require('internal/js_stream_socket');
const { Buffer } = require('buffer');
const debug = require('internal/util/debuglog').debuglog('tls');
let debug = require('internal/util/debuglog').debuglog('tls', (fn) => {
debug = fn;
});
const { TCP, constants: TCPConstants } = internalBinding('tcp_wrap');
const tls_wrap = internalBinding('tls_wrap');
const { Pipe, constants: PipeConstants } = internalBinding('pipe_wrap');
Expand Down
7 changes: 6 additions & 1 deletion lib/child_process.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,12 @@ const {
getSystemErrorName
} = require('internal/util');
const { isArrayBufferView } = require('internal/util/types');
const debug = require('internal/util/debuglog').debuglog('child_process');
let debug = require('internal/util/debuglog').debuglog(
'child_process',
(fn) => {
debug = fn;
}
);
const { Buffer } = require('buffer');
const { Pipe, constants: PipeConstants } = internalBinding('pipe_wrap');
const {
Expand Down
4 changes: 3 additions & 1 deletion lib/https.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,9 @@ const {
kServerResponse
} = require('_http_server');
const { ClientRequest } = require('_http_client');
const debug = require('internal/util/debuglog').debuglog('https');
let debug = require('internal/util/debuglog').debuglog('https', (fn) => {
debug = fn;
});
const { URL, urlToOptions, searchParamsSymbol } = require('internal/url');
const { IncomingMessage, ServerResponse } = require('http');
const { kIncomingMessage } = require('_http_common');
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/http2/core.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -159,7 +159,9 @@ const { UV_EOF } = internalBinding('uv');

const { StreamPipe } = internalBinding('stream_pipe');
const { _connectionListener: httpConnectionListener } = http;
const debug = require('internal/util/debuglog').debuglog('http2');
let debug = require('internal/util/debuglog').debuglog('http2', (fn) => {
debug = fn;
});

// TODO(addaleax): See if this can be made more efficient by figuring out
// whether debugging is enabled before we perform any further steps. Currently,
Expand Down
7 changes: 6 additions & 1 deletion lib/internal/js_stream_socket.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,12 @@ const assert = require('internal/assert');
const { Socket } = require('net');
const { JSStream } = internalBinding('js_stream');
const uv = internalBinding('uv');
const debug = require('internal/util/debuglog').debuglog('stream_socket');
let debug = require('internal/util/debuglog').debuglog(
'stream_socket',
(fn) => {
debug = fn;
}
);
const { owner_symbol } = require('internal/async_hooks').symbols;
const { ERR_STREAM_WRAP } = require('internal/errors').codes;

Expand Down
4 changes: 3 additions & 1 deletion lib/internal/main/worker_thread.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,9 @@ const {
} = require('internal/process/execution');

const publicWorker = require('worker_threads');
const debug = require('internal/util/debuglog').debuglog('worker');
let debug = require('internal/util/debuglog').debuglog('worker', (fn) => {
debug = fn;
});

const assert = require('internal/assert');

Expand Down
4 changes: 3 additions & 1 deletion lib/internal/modules/cjs/helpers.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,9 @@ const path = require('path');
const { pathToFileURL, fileURLToPath } = require('internal/url');
const { URL } = require('url');

const debug = require('internal/util/debuglog').debuglog('module');
let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
debug = fn;
});

function loadNativeModule(filename, request) {
const mod = NativeModule.map.get(filename);
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/modules/cjs/loader.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -245,7 +245,9 @@ ObjectDefineProperty(Module.prototype, 'parent', {
) : getModuleParent
});

const debug = require('internal/util/debuglog').debuglog('module');
let debug = require('internal/util/debuglog').debuglog('module', (fn) => {
debug = fn;
});
Module._debug = deprecate(debug, 'Module._debug is deprecated.', 'DEP0077');

// Given a module name, and a list of paths to test, returns the first
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/modules/esm/create_dynamic_module.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,9 @@ const {
Set,
} = primordials;

const debug = require('internal/util/debuglog').debuglog('esm');
let debug = require('internal/util/debuglog').debuglog('esm', (fn) => {
debug = fn;
});

function createImport(impt, index) {
const imptPath = JSONStringify(impt);
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/modules/esm/module_map.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,9 @@ const ModuleJob = require('internal/modules/esm/module_job');
const {
SafeMap,
} = primordials;
const debug = require('internal/util/debuglog').debuglog('esm');
let debug = require('internal/util/debuglog').debuglog('esm', (fn) => {
debug = fn;
});
const { ERR_INVALID_ARG_TYPE } = require('internal/errors').codes;
const { validateString } = require('internal/validators');

Expand Down
6 changes: 3 additions & 3 deletions lib/internal/modules/esm/translators.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,9 @@ const { defaultTransformSource } = require(
const createDynamicModule = require(
'internal/modules/esm/create_dynamic_module');
const { fileURLToPath, URL } = require('url');
const { debuglog } = require('internal/util/debuglog');
let debug = require('internal/util/debuglog').debuglog('esm', (fn) => {
debug = fn;
});
const { emitExperimentalWarning } = require('internal/util');
const {
ERR_UNKNOWN_BUILTIN_MODULE,
Expand All @@ -43,8 +45,6 @@ const { getOptionValue } = require('internal/options');
const experimentalImportMetaResolve =
getOptionValue('--experimental-import-meta-resolve');

const debug = debuglog('esm');

const translators = new SafeMap();
exports.translators = translators;

Expand Down
4 changes: 3 additions & 1 deletion lib/internal/policy/manifest.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,9 @@ const {
ERR_MANIFEST_INVALID_RESOURCE_FIELD,
ERR_MANIFEST_UNKNOWN_ONERROR,
} = require('internal/errors').codes;
const debug = require('internal/util/debuglog').debuglog('policy');
let debug = require('internal/util/debuglog').debuglog('policy', (fn) => {
debug = fn;
});
const SRI = require('internal/policy/sri');
const crypto = require('crypto');
const { Buffer } = require('buffer');
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/repl/history.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,9 @@ const { Interface } = require('readline');
const path = require('path');
const fs = require('fs');
const os = require('os');
const debug = require('internal/util/debuglog').debuglog('repl');
let debug = require('internal/util/debuglog').debuglog('repl', (fn) => {
debug = fn;
});
const { clearTimeout, setTimeout } = require('timers');

// XXX(chrisdickinson): The 15ms debounce value is somewhat arbitrary.
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/repl/utils.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,9 @@ const {
inspect,
} = require('internal/util/inspect');

const debug = require('internal/util/debuglog').debuglog('repl');
let debug = require('internal/util/debuglog').debuglog('repl', (fn) => {
debug = fn;
});

const previewOptions = {
colors: false,
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/source_map/prepare_stack_trace.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,9 @@ const {
Error,
} = primordials;

const debug = require('internal/util/debuglog').debuglog('source_map');
let debug = require('internal/util/debuglog').debuglog('source_map', (fn) => {
debug = fn;
});
const { getStringWidth } = require('internal/util/inspect');
const { readFileSync } = require('fs');
const { findSourceMap } = require('internal/source_map/source_map_cache');
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/source_map/source_map_cache.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,9 @@ function ObjectGetValueSafe(obj, key) {

// See https://sourcemaps.info/spec.html for SourceMap V3 specification.
const { Buffer } = require('buffer');
const debug = require('internal/util/debuglog').debuglog('source_map');
let debug = require('internal/util/debuglog').debuglog('source_map', (fn) => {
debug = fn;
});
const { dirname, resolve } = require('path');
const fs = require('fs');
const { getOptionValue } = require('internal/options');
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/stream_base_commons.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,9 @@ const kAfterAsyncWrite = Symbol('kAfterAsyncWrite');
const kHandle = Symbol('kHandle');
const kSession = Symbol('kSession');

const debug = require('internal/util/debuglog').debuglog('stream');
let debug = require('internal/util/debuglog').debuglog('stream', (fn) => {
debug = fn;
});
const kBuffer = Symbol('kBuffer');
const kBufferGen = Symbol('kBufferGen');
const kBufferCb = Symbol('kBufferCb');
Expand Down
4 changes: 3 additions & 1 deletion lib/internal/timers.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -113,7 +113,9 @@ const L = require('internal/linkedlist');
const PriorityQueue = require('internal/priority_queue');

const { inspect } = require('internal/util/inspect');
const debug = require('internal/util/debuglog').debuglog('timer');
let debug = require('internal/util/debuglog').debuglog('timer', (fn) => {
debug = fn;
});

// *Must* match Environment::ImmediateInfo::Fields in src/env.h.
const kCount = 0;
Expand Down
25 changes: 14 additions & 11 deletions lib/internal/util/debuglog.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,8 @@ function emitWarningIfNeeded(set) {
}
}

function noop() {}

function debuglogImpl(set) {
set = set.toUpperCase();
if (debugs[set] === undefined) {
Expand All @@ -48,7 +50,7 @@ function debuglogImpl(set) {
process.stderr.write(format('%s %s: %s\n', set, coloredPID, msg));
};
} else {
debugs[set] = null;
debugs[set] = noop;
}
}
return debugs[set];
Expand All @@ -58,16 +60,17 @@ function debuglogImpl(set) {
// 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.
function debuglog(set) {
let debug;
return function(...args) {
if (debug === undefined) {
// Only invokes debuglogImpl() when the debug function is
// called for the first time.
debug = debuglogImpl(set);
}
if (debug !== null)
debug(...args);
function debuglog(set, cb) {
let debug = (...args) => {
// Only invokes debuglogImpl() when the debug function is
// called for the first time.
debug = debuglogImpl(set);
if (typeof cb === 'function')
cb(debug);
debug(...args);
};
return (...args) => {
debug(...args);
};
Comment on lines +63 to 74
Copy link
Member

@himself65 himself65 Mar 14, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about this?

Suggested change
function debuglog(set, cb) {
let debug = (...args) => {
// Only invokes debuglogImpl() when the debug function is
// called for the first time.
debug = debuglogImpl(set);
if (typeof cb === 'function')
cb(debug);
debug(...args);
};
return (...args) => {
debug(...args);
};
function debuglog(set) {
let debug = (...args) => {
// Only invokes debuglogImpl() when the debug function is
// called for the first time.
debug = debuglogImpl(set);
debug(...args);
};
const state = { called: false };
return ((...args) => {
if(!this.called) {
debug(...args);
this.called = true;
} else {
debug(...args);
}
}).bind(state);

just like

node/lib/events.js

Lines 426 to 432 in ec204d8

function _onceWrap(target, type, listener) {
const state = { fired: false, wrapFn: undefined, target, type, listener };
const wrapped = onceWrapper.bind(state);
wrapped.listener = listener;
state.wrapFn = wrapped;
return wrapped;
}

Copy link
Member

@himself65 himself65 Mar 14, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

because I don't think let debug = fn('xxx', v => debug = v) is a good code style

Copy link
Contributor Author

@mscdex mscdex Mar 14, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The suggested change is basically what the code was doing before. Having a callback is the only way to be able to avoid the wrapper function and utilizing it provides a further, noticeable performance improvement.

Copy link
Member

@himself65 himself65 Mar 14, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, I understand

Copy link
Member

@jasnell jasnell Mar 16, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fairly certain this is because of the way V8 optimizes but that's only a guess. It's interesting that it's such a big perf difference.

}

Expand Down
4 changes: 3 additions & 1 deletion lib/internal/worker.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,9 @@ const kOnErrorMessage = Symbol('kOnErrorMessage');
const kParentSideStdio = Symbol('kParentSideStdio');

const SHARE_ENV = SymbolFor('nodejs.worker_threads.SHARE_ENV');
const debug = require('internal/util/debuglog').debuglog('worker');
let debug = require('internal/util/debuglog').debuglog('worker', (fn) => {
debug = fn;
});

let cwdCounter;

Expand Down
4 changes: 3 additions & 1 deletion lib/internal/worker/io.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,9 @@ const {
const { Readable, Writable } = require('stream');
const EventEmitter = require('events');
const { inspect } = require('internal/util/inspect');
const debug = require('internal/util/debuglog').debuglog('worker');
let debug = require('internal/util/debuglog').debuglog('worker', (fn) => {
debug = fn;
});

const kIncrementsPortRef = Symbol('kIncrementsPortRef');
const kName = Symbol('kName');
Expand Down
4 changes: 3 additions & 1 deletion lib/net.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,9 @@ const {
const EventEmitter = require('events');
const stream = require('stream');
const { inspect } = require('internal/util/inspect');
const debug = require('internal/util/debuglog').debuglog('net');
let debug = require('internal/util/debuglog').debuglog('net', (fn) => {
debug = fn;
});
const { deprecate } = require('internal/util');
const {
isIP,
Expand Down
4 changes: 3 additions & 1 deletion lib/repl.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -88,7 +88,9 @@ const CJSModule = require('internal/modules/cjs/loader').Module;
let _builtinLibs = [...CJSModule.builtinModules]
.filter((e) => !e.startsWith('_') && !e.includes('/'));
const domain = require('domain');
const debug = require('internal/util/debuglog').debuglog('repl');
let debug = require('internal/util/debuglog').debuglog('repl', (fn) => {
debug = fn;
});
const {
codes: {
ERR_CANNOT_WATCH_SIGINT,
Expand Down
4 changes: 3 additions & 1 deletion lib/timers.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,9 @@ const {
promisify: { custom: customPromisify },
deprecate
} = require('internal/util');
const debug = require('internal/util/debuglog').debuglog('timer');
let debug = require('internal/util/debuglog').debuglog('timer', (fn) => {
debug = fn;
});
const { validateCallback } = require('internal/validators');

const {
Expand Down
4 changes: 3 additions & 1 deletion test/sequential/test-util-debug.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,7 +118,9 @@ function child(section) {
value: tty.WriteStream.prototype.hasColors
});
// eslint-disable-next-line no-restricted-syntax
const debug = util.debuglog(section);
const debug = util.debuglog(section, common.mustCall((cb) => {
assert.strictEqual(typeof cb, 'function');
}));
debug('this', { is: 'a' }, /debugging/);
debug('num=%d str=%s obj=%j', 1, 'a', { foo: 'bar' });
console.log('ok');
Expand Down