module: print amount of load time of a module

[H4ad]

I was investigating why npm is slow and I started to figure out that was caused by it loading a lot of modules/js files, but I didn't know what are those modules or even how much time it took to load them.

So, this implementation came to my mind, and I used with the following commands:

NODE_DEBUG=module_cjs ~/Projects/opensource/node-copy-4/out/Release/node ./bin/npm-cli.js run echo --silent &> trace-node.txt

The log looks like this:

MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/commands/run-script.js] [../utils/did-you-mean.js]: 0.499ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/commands/run-script.js] [../utils/is-windows.js]: 0.102ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/base-command.js] [path]: 0.005ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/base-command.js] [@npmcli/config/lib/definitions]: 0.001ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/workspaces/get-workspaces.js] [path]: 0.003ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/workspaces/get-workspaces.js] [@npmcli/map-workspaces]: 0.051ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/workspaces/get-workspaces.js] [minimatch]: 0.055ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/workspaces/get-workspaces.js] [@npmcli/package-json]: 0.044ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/base-command.js] [./workspaces/get-workspaces.js]: 0.346ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/base-command.js] [./utils/cmd-list]: 0.027ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/base-command.js] [./utils/log-shim.js]: 0.012ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/commands/run-script.js] [../base-command.js]: 0.638ms
MODULE_CJS 413480 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/npm.js] [./commands/run-script.js]: 12.02ms

If we try to clean a little bit:

$ cat trace-node.txt | tr . , | sort -sbng -k5,16n -t ''| tr , .> formatted-timing.txt

The output was:

MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/@npmcli/agent/lib/proxy.js] [socks-proxy-agent]: 13.046ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/npm.js] [./commands/run-script.js]: 13.548ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/cli-entry.js] [./npm.js]: 16.606ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/@npmcli/agent/lib/index.js] [./proxy.js]: 18.73ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/cache/entry.js] [cacache]: 19.421ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/remote.js] [@npmcli/agent]: 20.019ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/cache/entry.js] [../remote.js]: 21.397ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/cache/index.js] [./entry.js]: 42.496ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/fetch.js] [./cache/index.js]: 42.8ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/index.js] [./fetch.js]: 46.18ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/npm-registry-fetch/lib/index.js] [make-fetch-happen]: 47.044ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/utils/replace-info.js] [npm-registry-fetch]: 64.717ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/utils/error-message.js] [./replace-info.js]: 64.867ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/utils/exit-handler.js] [./error-message.js]: 73.463ms
MODULE_TIMER 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/cli-entry.js] [./utils/exit-handler.js]: 85.115ms
MODULE_TIMER 413856 [] [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/bin/npm-cli.js]: 117.08ms

In this way, is very clear what is taking a lot of time to load npm, and I actually already opened a PR to fix one of the issues that appeared in this log (npm/cli#7314)

---

@joyeecheung suggest to include also the support for trace_events, so I created the debugWithTimer to introduce support for both ways extract information, via log or via trace:

$ ./out/Release/node --trace-event-categories node.module_timer --trace-event-file-pattern 'trace-events.log'~/Projects/opensource/performance-analysis/npm-cli/bin/npm-cli.js run echo --silent

This will generate a trace-events.log file that can be imported on chrome://tracing or Perfetto UI to generate the following graph:

To be easier to read, I introduce two labels on the debugWithTimer, the first one will be for logging via NODE_DEBUG and the second one will be used at the trace.

/cc @nodejs/performance

[nodejs-github-bot]

Review requested:

• @nodejs/loaders

[GeoffreyBooth]

Could this perhaps get its own label in NODE_DEBUG? I feel like optimizing module load time is an infrequent use case for debugging modules and these logging lines must be very spammy.

[H4ad]

@GeoffreyBooth I changed to TIMING_MODULE_CJS, we can also add support for esm under TEST_MODULE_ESM, and then we can measure both cases.

I didn't found any good alternative for this name, so I'm open to change this to another one if needed.

[richardlau]

Conceptually this feels more like something for trace_events than NODE_DEBUG?

[H4ad]

@richardlau Maybe I'm not familiar with trace_events but from what I see in the source code, I think it won't be as useful as having it as NODE_DEBUG since to be able to listen to the events we need to import trace_events and then createTracing.

The benefits of emitting these events through NODE_DEBUG is because it is very easy to listen to these events without any additional code, plus even importing trace_events will affect the events that will be emitted by this new debug, so I don't ' I don't think the implementation with trace_events will be as useful as this.

[joyeecheung]

createTracing() is for user-land tracing to get hooked into our tracing infra. Pretty sure internally we can just use internalBinding('trace_events').trace, which is already what we load during startup.

[joyeecheung]

Actually console.time() and console.timeEnd() is hooked into the tracing infra via internalBinding('trace_events').trace too. So for timing-related traces, adding some sort of support in debuglog to also emit traces via internalBinding('trace_events').trace sounds like a good idea. You get to both check out human-readable information via stdout, and get a trace file you can visualize using e.g. DevTools.

[H4ad]

@joyeecheung I changed the implementation to match what we discussed, I liked this new way, it will print in the stderr if the NODE_DEBUG=module_cjs or it will trace if the category is node. debuglog_{set}, in this case, node.debuglog_module_cjs.

I still have some tests to fix but in general the implementation is good enough to get some reviews.

[H4ad]

If we use the chrome://tracing, we can see what module is loading which module (I think we can improving this visualization).

[H4ad]

I fixed the tests and I also changed a little bit the visualization for trace, I updated the PR to include the new graph and the new logging example.

[RafaelGSS]

Can you update the PR to include only the changes this PR is about? I can see some linting and type changes.

[rluvaton]

@H4ad Is it possible to backport this to node 20?

[H4ad]

I don't know, usually we need someone from the release team to select this PR first to see if there is any conflict, only if we have conflicts we need a manual backport.

[joyeecheung]

Tentatively backported in #56927 - backporting this reduces the conflicts, though it seems associated with some other later commits, some included regressions, so only tentatively backporting it together with the associated commits that I found, which seemed safe enough.

[joyeecheung]

Backing it out from #56927 to avoid introducing surface for regressions.