[BUG] npm exec --workspaces very slow

gavinsharp commented 2 years ago

Is there an existing issue for this?

[X] I have searched the existing issues

This issue exists in the latest npm version

[X] I am using the latest npm

Current Behavior

We have a monorepo using npm workspaces, containing ~70 workspaces/packages.

We noticed that running npm exec --workspaces (for example, npm exec --workspaces --call 'pwd') at the top-level of this monorepo was incredibly slow - the npm process would be pegged at 100% CPU and it would take multiple seconds to print the directory path for each workspace.

The overall run time of npm exec --workspaces --call 'pwd' can take several minutes.

I was able to bisect NPM release versions to identify that this command was fast in version 8.7.0, but slow in version 8.8.0, so it appears that https://github.com/npm/cli/pull/4643 introduced the slowness (cc @ruyadorno). Indeed if I locally revert the change from that PR (modified revert due to subsequent changes from #5250), the performance issue disappears:

--- /Users/gavin/.nvm/versions/node/v16.17.0/lib/node_modules/npm/lib/commands/exec.js  2022-09-14 15:12:56.000000000 -0400
+++ /Users/gavin/.nvm/versions/node/v16.17.0/lib/node_modules/npm/lib/commands/exec-2.js    2022-09-14 15:12:37.000000000 -0400
@@ -25,7 +25,7 @@

   async exec (_args, { locationMsg, runPath } = {}) {
     // This is where libnpmexec will look for locally installed packages
-    const localPrefix = this.npm.localPrefix
+    const localPrefix = runPath ? runPath : this.npm.localPrefix

Expected Behavior

npm exec --workspaces --call 'pwd' should very quickly (<2s) print out all workspace directories.

Steps To Reproduce

In a large monorepo with ~70 workspaces
With a default workspaces config
Run npm exec --workspaces --call 'pwd'
See slowness

Environment

npm: 8.19.2
Node.js: 16.17.0
OS Name: macOS 12.5.1
System Model Name: Macbook Pro (2021 M1 Max)

npm config:

; node bin location = /Users/gavin/.nvm/versions/node/v16.17.0/bin/node
; node version = v16.17.0
; npm local prefix = /Users/gavin/dev/league-web
; npm version = 8.19.2
; cwd = /Users/gavin/dev/league-web
; HOME = /Users/gavin

ruyadorno commented 2 years ago

That's an intriguing one, nice find @gavinsharp thanks for submitting it!

The linked PRs and codepaths doesn't really look like they are the actual source of the problem but rather pointing that the problem manifests once libnpmexec is properly wired up with the cli. That said, tweaking localPrefix to point to runPath is not really the way this API is supposed to work, since libnpmexec path param is supposed to be pointing to the project root.

It wouldn't surprise me if the problem is actually in @npmcli/run-script path logic: https://github.com/npm/run-script/blob/c7d1400956b654c929a885aba4e452d4198297d1/lib/set-path.js but I would rather recommend some profiling first rather than jumping into conclusions.

Sigill commented 1 year ago

I believe I've identified the culprit.

I was investigating why, in our monorepo that contains 35 workspaces, I encounter those awful performances:

$ time npm exec rimraf dist

real    0m3.991s
user    0m6.526s
sys     0m2.711s

$ time ./node_modules/.bin/rimraf dist

real    0m0.101s
user    0m0.090s
sys     0m0.019s

dist/ directory was empty in both cases, and according to these numbers, npm exec/npx appears to add a huge overhead.

Running npm exec in verbose mode yields that:

0 verbose cli /home/[...]/.nvm/versions/node/v16.19.1/bin/node /home/[...]/.nvm/versions/node/v16.19.1/bin/npm
1 info using npm@8.19.3
2 info using node@v16.19.1
3 timing npm:load:whichnode Completed in 0ms
4 timing config:load:defaults Completed in 4ms
5 timing config:load:file:/home/[...]/.nvm/versions/node/v16.19.1/lib/node_modules/npm/npmrc Completed in 1ms
6 timing config:load:builtin Completed in 1ms
7 timing config:load:cli Completed in 3ms
8 timing config:load:env Completed in 0ms
9 info found workspace root at /home/[...]
10 timing config:load:file:/home/[...]/.npmrc Completed in 1ms
11 timing config:load:project Completed in 1684ms
12 timing config:load:file:/home/[...]/.npmrc Completed in 1ms
13 timing config:load:user Completed in 1ms
14 timing config:load:file:/home/[...]/.nvm/versions/node/v16.19.1/etc/npmrc Completed in 0ms
15 timing config:load:global Completed in 0ms
16 timing config:load:validate Completed in 2ms
17 timing config:load:credentials Completed in 1ms
18 timing config:load:setEnvs Completed in 0ms
19 timing config:load Completed in 1697ms
20 timing npm:load:configload Completed in 1698ms
21 timing npm:load:mkdirpcache Completed in 1ms
22 timing npm:load:mkdirplogs Completed in 0ms
23 verbose title npm exec rimraf dist
24 verbose argv "exec" "--loglevel" "verbose" "rimraf" "dist"
25 timing npm:load:setTitle Completed in 1ms
26 timing config:load:flatten Completed in 3ms
27 timing npm:load:display Completed in 7ms
28 verbose logfile logs-max:10 dir:/home/[...]/..npm/_logs
29 verbose logfile /home/[...]/.npm/_logs/2023-02-24T10_36_59_277Z-debug-0.log
30 timing npm:load:logFile Completed in 3ms
31 timing npm:load:timers Completed in 0ms
32 timing npm:load:configScope Completed in 0ms
33 timing npm:load Completed in 1711ms
34 silly logfile start cleaning logs, removing 2 files
35 silly logfile done cleaning log files
36 timing command:exec Completed in 1743ms
37 verbose exit 0
38 timing npm Completed in 3574ms
39 info ok

Let me draw your attention to:

11 timing config:load:project Completed in 1684ms
36 timing command:exec Completed in 1743ms

With a debugger, I identified this line: https://github.com/npm/map-workspaces/blob/e54d4254ab8d712e03cd3fbd4a46fd1bc98c8572/lib/index.js#L101, which basically list every directory matching packages/**/*/, examples/**/*/ and doc/**/*/ from the root of my project.

With a quick and dirty instrumentation, I get:

pGlob found 1489 items matching packages/**/*/, took 856.1076507568359 ms.
pGlob found 1067 items matching examples/**/*/, took 665.214427947998 ms.
pGlob found 175 items matching doc/**/*/, took 57.504862785339355 ms.
pGlob found 1489 items matching packages/**/*/, took 744.4372606277466 ms.
pGlob found 1067 items matching examples/**/*/, took 673.1901254653931 ms.
pGlob found 175 items matching doc/**/*/, took 53.704115867614746 ms.
(yes, it's done twice)

For a total of approx 3s.

Running npm exec --workspaces --call 'pwd' (what @gavinsharp was trying to do) takes 1min45s, those globs being done for each of my 35 workspaces.

I've tried node-glob alone, outside of npm, and the performances are indeed awful. I'll have a look.

Nonetheless, I'm wondering why we need to glob all those directories, multiple times (and with the same parameters).\ I imagine that it might make sense for operations npm install, but for a simple npm exec rimraf... something feels broken.

Sigill commented 1 year ago

I've just noticed that the packages/**/*, examples/**/* and doc/**/* patterns are actually what is defined as workspaces in the package.json of my project.

Switching to an explicit list of directories removes a lot of overhead:

$ time npm exec rimraf dist

real    0m0.628s
user    0m0.676s
sys     0m0.174s

It seems there's still a 500ms overhead due to npm, but from what I can see, that's just the overhead of loading every npm dependencies.

Running npm exec --workspaces --call 'pwd' now only takes 45s. That's still bad, but better.

redonkulus commented 1 year ago

I wonder if anything from this blog post is related https://marvinh.dev/blog/speeding-up-javascript-ecosystem-part-4/

npm / cli