node
node copied to clipboard
nodejs
module: print amount of load time of a module
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_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/@npmcli/agent/lib/proxy.js] [socks-proxy-agent]: 13.046ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/npm.js] [./commands/run-script.js]: 13.548ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/cli-entry.js] [./npm.js]: 16.606ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/@npmcli/agent/lib/index.js] [./proxy.js]: 18.73ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/cache/entry.js] [cacache]: 19.421ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/remote.js] [@npmcli/agent]: 20.019ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/cache/entry.js] [../remote.js]: 21.397ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/cache/index.js] [./entry.js]: 42.496ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/fetch.js] [./cache/index.js]: 42.8ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/make-fetch-happen/lib/index.js] [./fetch.js]: 46.18ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/node_modules/npm-registry-fetch/lib/index.js] [make-fetch-happen]: 47.044ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/utils/replace-info.js] [npm-registry-fetch]: 64.717ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/utils/error-message.js] [./replace-info.js]: 64.867ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/utils/exit-handler.js] [./error-message.js]: 73.463ms
MODULE_CJS 413856 [/home/h4ad/Projects/opensource/performance-analysis/npm-cli/lib/cli-entry.js] [./utils/exit-handler.js]: 85.115ms
MODULE_CJS 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.debuglog_module_cjs --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
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.
@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.
Conceptually this feels more like something for trace_events than NODE_DEBUG?
@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.
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.
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.
@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.
If we use the chrome://tracing, we can see what module is loading which module (I think we can improving this visualization).
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.
I moved the new code entirely to debuglog as suggested by Joyee, I added more tests to ensure both trace-events and NODE_DEBUG are working correctly, and I also checked only startup time the presence of trace-categories flags and then replaced the functions to noop.
I leave a TODO for myself to optimize the isTraceCategoryEnabled to let this feature to be enabled at runtime.
@joyeecheung Should we support ending the trace even if the _load throws an unexpected error?
I was creating a trace for pnpm and for some reason, the trace was not ending, I changed the _load code to have a huge try/finally and then the trace was fixed.
Is this a scenario we want to support or can we ignore it?
even if the _load throws an unexpected error?
Where is that error coming from? I think most error paths are ending the timers here already? (especially the try-catch around module.load)?
From what I debug, the error is thrown when the module is not found.
Also, I read the source code of the functions that are called and there are other cases where it throws an error without a try-catch, like inside getExportsForCircularRequire, those cases will cause the trace to start but not end.
I added a huge try-catch to handle those cases to always end a trace.
EDIT: Sorry for the force-push, people are being very active these days on loader.js, so rebase was needed.
Hmm I see, the inner functions can throw too.
Can we minimize the changes by adding an internal helper in cjs/loader.js that wraps Module._load with a try-finally block that also do the timer calls? Then change the internals that call Module._load to call this helper instead. That was also what we did with wrapSafe etc. While some users might call Module._load directly I doubt we really want to support tracing for them? It seems to me users that do access internals of the CJS loader tend to be more interested in other prototype methods anyway. If it turns out users in the wild do invoke Module._load enough we can revisit to add the giant try catch block but otherwise we get a cleaner git history from avoiding all the indentation changes.
Actually putting try-catch around Module._load might have the additional benefit that...if users monkey-patch it (😅) we can also measure the time took in the monkey-patched Module._load (e.g. with Yarn pnp), which is usually just doing some additional thing in the loading process, but probably it's a good idea to measure the time taken in the whole thing in case the added code become bottleneck? And patching Module._load might be more common that invoking a non-patched version.
I added the wrapModuleLoad to implement the logic of tracing & recursion tracking.
But I also noticed a lot of places where _load is called directly, should we rewrite those places to call wrapModuleLoad?
Those places don't call requireDepth, so I don't think is planned, or if we change those places to call wrapModuleLoad, it will be a breaking change since is changing the requireDepth.
But I also noticed a lot of places where _load is called directly, should we rewrite those places to call wrapModuleLoad?
Yes.
Those places don't call requireDepth, so I don't think is planned, or if we change those places to call wrapModuleLoad, it will be a breaking change since is changing the requireDepth.
AFAICT those places aren't related to require() anyway (e.g. it's import cjs), so it's okay that they are not doing requireDepth. Probably out of the scope of this PR to try to fix them.
Sorry for taking so long to fix the issues, I was taking a break from OSS.
I fixed all the changes on the snapshot tests, since we introduced a new function in the call stack, I think the semver-minor already covers the "potential breaking change" of this new function.
This PR got bigger than I expected but I think is a worthy feature to have, once we merge it, I will start working on the support for ESM and dynamic enable of trace feature.
Failed to start CI
⚠ Something was pushed to the Pull Request branch since the last approving review. ✘ Refusing to run CI on potentially unsafe PRhttps://github.com/nodejs/node/actions/runs/8922123656
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
@joyeecheung The current CI is failing because the trace is emitting every string without escaping, so something like this:
console.time('C:\\wddd');
setTimeout(() => console.timeEnd('C:\\wddd'), 200);
Will emit an invalid JSON even on v22 because the output string will be:
"name":"time::C:\wddd",
Probably .replace('\\', '\\\\') on the trace label should be enough to fix this issue, and since we merge the implementation of console.time with debugWithTimer, this will fix both cases.
Any hints on how to proceed?
I added escaping for \\ and also a test to ensure it's working for console.time.
I also tried to fix all issues on Windows, so now it should pass all the tests (hopefully)
I got some errors from CI, one of them is:
not ok 2208 parallel/test-module-print-timing
18:02:18 ---
18:02:18 duration_ms: 340.76000
18:02:18 severity: fail
18:02:18 exitcode: 1
18:02:18 stack: |-
18:02:18 TAP version 13
18:02:18 # Subtest: should print the timing information for cjs
18:02:18 not ok 1 - should print the timing information for cjs
18:02:18 ---
18:02:18 duration_ms: 11.76897
18:02:18 location: '/home/iojs/build/workspace/node-test-commit-linux-containered/test/parallel/test-module-print-timing.mjs:10:1'
18:02:18 failureType: 'testCodeFailure'
18:02:18 error: |-
18:02:18 Expected values to be strictly equal:
18:02:18
18:02:18 127 !== 0
18:02:18
18:02:18 code: 'ERR_ASSERTION'
18:02:18 name: 'AssertionError'
18:02:18 expected: 0
18:02:18 actual: 127
18:02:18 operator: 'strictEqual'
18:02:18 stack: |-
18:02:18 TestContext.<anonymous> (file:///home/iojs/build/workspace/node-test-commit-linux-containered/test/parallel/test-module-print-timing.mjs:17:10)
18:02:18 async Test.run (node:internal/test_runner/test:842:9)
18:02:18 async Test.processPendingSubtests (node:internal/test_runner/test:550:7)
Link: https://ci.nodejs.org/job/node-test-commit-linux-containered/nodes=ubuntu2204_sharedlibs_openssl30_x64/43597/consoleFull
Which is something like: usually indicates that the command or binary being executed within a container could not be found which does not make sense since I'm using execPath and -e.
The other one is on Windows, the build is just failing and I didn't find the reason: https://ci.nodejs.org/job/node-compile-windows-debug/nodes=win-vs2022/22042/consoleFull
@nodejs/build any hints?