lib: improve debuglog() performance

PR-URL: https://github.com/nodejs/node/pull/32260
Reviewed-By: James M Snell <jasnell@gmail.com>

lib/_http_agent.js

@@ -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: {

lib/_http_common.js

@@ -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;

lib/_stream_readable.js

@@ -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 {

lib/_tls_wrap.js

@@ -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');

lib/child_process.js

@@ -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 {

lib/https.js

@@ -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');

lib/internal/http2/core.js

@@ -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,

lib/internal/js_stream_socket.js

@@ -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;
 

lib/internal/main/worker_thread.js

@@ -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');
 

lib/internal/modules/cjs/helpers.js

@@ -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);

lib/internal/modules/cjs/loader.js

@@ -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

lib/internal/modules/esm/create_dynamic_module.js

@@ -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);

lib/internal/modules/esm/module_map.js

@@ -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');
 

lib/internal/modules/esm/translators.js

@@ -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,
@@ -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;
 

lib/internal/policy/manifest.js

@@ -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');

lib/internal/repl/history.js

@@ -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.

lib/internal/repl/utils.js

@@ -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,

lib/internal/source_map/prepare_stack_trace.js

@@ -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');

lib/internal/source_map/source_map_cache.js

@@ -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');

lib/internal/stream_base_commons.js

@@ -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');

lib/internal/timers.js

@@ -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;

lib/internal/util/debuglog.js

@@ -35,6 +35,8 @@ function emitWarningIfNeeded(set) {
   }
 }
 
+function noop() {}
+
 function debuglogImpl(set) {
   set = set.toUpperCase();
   if (debugs[set] === undefined) {
@@ -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];
@@ -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) {
+function debuglog(set, cb) {
-  let debug;
+  let debug = (...args) => {
-  return function(...args) {
+    // Only invokes debuglogImpl() when the debug function is
-    if (debug === undefined) {
+    // called for the first time.
-      // Only invokes debuglogImpl() when the debug function is
+    debug = debuglogImpl(set);
-      // called for the first time.
+    if (typeof cb === 'function')
-      debug = debuglogImpl(set);
+      cb(debug);
-    }
+    debug(...args);
-    if (debug !== null)
+  };
-      debug(...args);
+  return (...args) => {
+    debug(...args);
   };
 }
 

lib/internal/worker.js

@@ -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;
 

lib/internal/worker/io.js

@@ -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');

lib/net.js

@@ -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,

lib/repl.js

@@ -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,

lib/timers.js

@@ -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 {

test/sequential/test-util-debug.js

@@ -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');