Skip to content

module: print amount of load time of a module

Rodrigo Muino Tomonari requested to merge github/fork/H4ad/trace-load-module into main

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 (https://github.com/npm/cli/pull/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:

image

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

Merge request reports