Module loader customization hooks performance overhead

[uhyo]

Hello, I'm playing around with the module.register API and I observe a noticeable performance penalty when it hooks into CJS -> CJS loading.

Example setup

hooks.mjs:

import { readFile } from "fs/promises";
const startTime = performance.now();

export async function resolve(specifier, context, defaultResolve) {
  const result = await defaultResolve(specifier, context);
  console.log((performance.now() - startTime).toFixed(0), "resolve", specifier);
  return result;
}

export async function load(url, context, nextLoad) {
  const result = await nextLoad(url, context);
  if (result.format === "commonjs") {
    // This seems the way to opt into the new CJS loader
    result.source ??= await readFile(
      new URL(result.responseURL ?? url),
      "utf-8"
    );
  }
  console.log((performance.now() - startTime).toFixed(0), "load", context);
  return result;
}

main.mjs:

// graphql is just an example of a middle-sized CJS package
import graphql from "graphql";

command:

node --import 'data:text/javascript,import { register } from "node:module"; import { pathToFileURL } from "node:url"; register("./hooks.mjs", pathToFileURL("./"));' ./main.mjs

In this example, no-op customization hooks are set up. Ideally the overhead of the hooks should be minimum, but it adds around 400ms on my machine (Node.js 20.21.0, WSL2), making the whole process 4x slower.

Without hooks:

$ time node main.mjs

real    0m0.138s
user    0m0.154s
sys     0m0.045s

With hooks:

$ time node --import 'data:text/javascript,import { register } from "node:module"; import { pathToFileURL } from "node:url"; register("./hooks.mjs", pathToFileURL("./"));' ./main.mjs

real    0m0.574s
user    0m0.488s
sys     0m0.608s

Most of the added time is spent for communicating with the customization hooks worker synchronously. This can be observed by NODE_DEBUG=esm.

Excerpts from `NODE_DEBUG=esm` debug logs

ESM 13754: post sync message to worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/astFromValue.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ],
  transferList: undefined
}
ESM 13754: wait for sync response from worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/astFromValue.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ]
}
ESM 13754: wait for sync response from worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/astFromValue.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ]
}
ESM 13754: got sync response from worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/astFromValue.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ]
}
ESM 13754: post sync message to worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/sortValueNode.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ],
  transferList: undefined
}
ESM 13754: wait for sync response from worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/sortValueNode.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ]
}
ESM 13754: wait for sync response from worker {
  method: 'resolve',
  args: [
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/sortValueNode.js',
    'file:///home/uhyo/repos/nodejs-hooks-perf/node_modules/graphql/utilities/findBreakingChanges.js',
    [Object: null prototype] {}
  ]
}

Likely using Atomics for waiting async operations synchronously has inevitable overheads, which I hope improvements can be made.

However, there is another questionable behavior. Instrumenting the hooks code shows that the hooks are run only a few times (resolve twice and load twice):

2 resolve file:///home/uhyo/repos/nodejs-hooks-perf/main.mjs
4 load { format: 'module', importAttributes: {} }
8 resolve graphql
10 load { format: 'commonjs', importAttributes: {} }

This suggests that the registered hooks code is run only when doing ESM -> ESM or ESM -> CJS imports, but not for CJS -> CJS requires. In the CJS -> CJS case, the hooks code is not run, while Node.js still performs communication with the customization hooks worker. I really wonder what work is done, since most of the performance overhead is produced here.

EDIT: this wasn't right. My hooks were indeed called but logs weren't printed to the console. I created a separate issue for this: #51668.

---

I am creating a tool that can read some configuration files written in TypeScript. Currently the module customization hooks are taking 90% of CLI run time, so I am looking for ways to speed up this. My investigation showed the above questionable behavior and I'm really curious why Node.js behaves like this.

Can anyone explain this? Of course, idea for actual performance improvement is super welcome. Thanks!

[uhyo]

Oh sorry, after further debugging it was just that console log from the worker was not redirected to the main thread. My hooks were actually called.

[aduh95]

I expect most of the perf difference is the spawning of the loaders thread.

/cc @nodejs/loaders

[uhyo]

As far as I researched, this isn't true unfortunately. The perf difference seems to grow as more CJS files are loaded.

In my environment, the diff for import graphql from "graphql" is about 400ms, while the diff for import grpahql from "graphql"; import jsdom from "jsdom" grows to 1200ms.