npm ci; 45 seconds elapses between arborist:ctor and idealTree:init

[rickhull]

What / Why

npm ci is taking about 5 minutes to complete, and I am investigating. I am redirecting npm's output to a log file, and in another session, I am writing a timestamp to the same file every 5 seconds. (For the record, npm's timing output is less than helpful in diagnosing where slowdowns are occurring).

After npm timing arborist:ctor Completed in 0ms, I am seeing around 45 seconds of elapsed wall clock time with no output, and then npm timing idealTree:init Completed in 1ms

When

On npm ci --offline --loglevel verbose --progress false

Where

npm ci on macOS 11.1 (Big Sur) on 2017 MBP (quad 3.1 GHz i7)

npm info using npm@7.3.0
npm info using node@v15.5.1

How

Current Behavior

Mon Jan 25 15:21:52 EST 2021
npm verb cli [
npm verb cli   '/usr/local/Cellar/node/15.5.1/bin/node',
npm verb cli   '/usr/local/bin/npm',
npm verb cli   'ci',
npm verb cli   '--offline',
npm verb cli   '--loglevel',
npm verb cli   'verbose',
npm verb cli   '--progress',
npm verb cli   'false'
npm verb cli ]
npm info using npm@7.3.0
npm info using node@v15.5.1
npm timing config:load:defaults Completed in 1ms
npm timing config:load:file:/usr/local/lib/node_modules/npm/npmrc Completed in 2ms
npm timing config:load:builtin Completed in 2ms
npm timing config:load:cli Completed in 1ms
npm timing config:load:env Completed in 1ms
npm timing config:load:file:/Users/rhull/axio/client/.npmrc Completed in 1ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/Users/rhull/.npmrc Completed in 0ms
npm timing config:load:user Completed in 0ms
npm timing config:load:file:/usr/local/etc/npmrc Completed in 3ms
npm timing config:load:global Completed in 3ms
npm timing config:load:cafile Completed in 0ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:setUserAgent Completed in 1ms
npm timing config:load:setEnvs Completed in 0ms
npm timing config:load Completed in 10ms
npm verb npm-session e4bdf1c0f8ab853c
npm timing npm:load Completed in 20ms
npm timing arborist:ctor Completed in 0ms
Mon Jan 25 15:21:57 EST 2021
Mon Jan 25 15:22:02 EST 2021
Mon Jan 25 15:22:07 EST 2021
Mon Jan 25 15:22:12 EST 2021
Mon Jan 25 15:22:17 EST 2021
Mon Jan 25 15:22:22 EST 2021
Mon Jan 25 15:22:27 EST 2021
Mon Jan 25 15:22:32 EST 2021
Mon Jan 25 15:22:37 EST 2021
npm timing idealTree:init Completed in 1ms
npm timing idealTree:userRequests Completed in 0ms
npm timing idealTree:#root Completed in 1ms
npm timing idealTree:buildDeps Completed in 1ms
npm timing idealTree:fixDepFlags Completed in 1ms
npm timing idealTree Completed in 8ms
npm timing reify:loadTrees Completed in 152ms
npm timing reify:diffTrees Completed in 54ms
npm timing reify:retireShallow Completed in 0ms
npm timing reify:createSparse Completed in 548ms
npm timing reifyNode:node_modules/npm Completed in 1183ms
npm timing arborist:ctor Completed in 0ms
npm timing reify:diffTrees Completed in 55ms
npm timing reify:loadBundles Completed in 1489ms
Mon Jan 25 15:22:42 EST 2021
Mon Jan 25 15:22:47 EST 2021
Mon Jan 25 15:22:52 EST 2021
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 13457ms

More context is above. Here is a focus on the area of concern:

npm timing arborist:ctor Completed in 0ms
Mon Jan 25 15:21:57 EST 2021
Mon Jan 25 15:22:02 EST 2021
Mon Jan 25 15:22:07 EST 2021
Mon Jan 25 15:22:12 EST 2021
Mon Jan 25 15:22:17 EST 2021
Mon Jan 25 15:22:22 EST 2021
Mon Jan 25 15:22:27 EST 2021
Mon Jan 25 15:22:32 EST 2021
Mon Jan 25 15:22:37 EST 2021
npm timing idealTree:init Completed in 1ms

Steps to Reproduce

Run npm ci --offline --loglevel verbose --progress false with my package-lock.json; inject timestamps every 5 seconds with another process.

Expected Behavior

45 seconds should not elapse between 2 output lines that show 1 ms elapsed. It would be nice to have more output for something that is taking so long. Whatever is happening during this 45 seconds -- is it expected behavior?

[rickhull]

I figured this is the right repo since the time is elapsing between arborist things. I can file this against npmcli or whatever is appropriate.

[isaacs]

Well that's a bit unusual, but I think I know what's causing it.

The timing printed out in those log lines is calculated by evaluating the time between process.emit('time', msg) and process.emit('timeEnd', msg). So it's not that there's 1ms elapsed between the arborist constructor and the the tree init event -- rather, the constructor takes 0ms, and the init takes 1ms, and in between those two, apparently something very slow is not being tracked at all.

Looking at the source of lib/ci.js in the npm cli, I see this:

  const arb = new Arborist({ ...npm.flatOptions, path: where })

  await Promise.all([
    arb.loadVirtual().catch(er => {
      log.verbose('loadVirtual', er.stack)
      const msg =
        'The `npm ci` command can only install with an existing package-lock.json or\n' +
        'npm-shrinkwrap.json with lockfileVersion >= 1. Run an install with npm@5 or\n' +
        'later to generate a package-lock.json file, then try again.'
      throw new Error(msg)
    }),
    rimraf(`${where}/node_modules/*`, { glob: { dot: true, nosort: true, silent: true } }),
  ])
  // npm ci should never modify the lockfile or package.json
  await arb.reify({ ...npm.flatOptions, save: false })

loadVirtual is just a single file read. However, if you have a lot of files in node_modules, then it could be taking a long time to delete them all recursively.

Do you see the same timing oddness if node_modules is empty?

[rickhull]

Thanks, this is super helpful. I suspect it is the deletion taking so long. There are a lot of node modules for this project. Also I am performing npm ci on a corporate machine with drive encryption and some phone-home stuff. I'll try your suggestion, but do you think it makes sense to add a timing statement for deletion step?

[isaacs]

Yes, I definitely think we should put a process.emit('time', 'npm-ci:rm') before it and process.emit('timeEnd', 'npm-ci:rm') when it completes.

[rickhull]

Confirmed, it's the deletion of node_modules taking 45 seconds. In my case, this is a React project and I'm on OS X Big Sur, with corporate watchdog software, and I think that stuff isn't working very well on Big Sur.

[rickhull]

I tried to put a PR together to add the timing statements. Should they go outside the Promise.all or does there need to be some restructuring? I'm also not sure how I can test my npmcli branch against my react project repo (so that my installed version of npm isn't active).

[isaacs]

No worries. The test needed a little bit of cleanup, but wasn't too hard. Also got rid of the glob, just to squeeze a few more ms out of the performance there. npm/cli#2573

[rickhull]

Excellent, thanks!