Progress bar noticeably slows down npm install

[zakjan]

Compare these runtimes of npm install:

$ rm -r node_modules
$ npm set progress=false
$ time npm install
npm install  19.91s user 2.66s system 71% cpu 31.667 total

$ rm -r node_modules
$ npm set progress=true
$ time npm install
npm install  33.26s user 3.19s system 74% cpu 48.733 total

Npm 3.5.2. Both commands were run with already warmed-up cache. Progress bar may be responsible for up to 50% slow down.

Original source: https://twitter.com/gavinjoyce/status/691783314261331969 by @GavinJoyce

[GavinJoyce]

I found the original report here whilst researching how I could make npm install faster.

[GavinJoyce]

It seems to yield a significant speed up for most people, all my colleagues in @intercom are seeing a significant boost. So far @kittens is the only one who hasn't reported a big difference:

https://twitter.com/sebmck/status/691911481114415104

I tried npm installing reactive-native and can see a major speed improvement with npm v3.5.3:

npm set progress=false && rm -rf ~/.npm && rm -rf node_modules && time npm install
npm install  70.27s user 22.12s system 120% cpu 1:16.85 total

npm set progress=true && rm -rf ~/.npm && rm -rf node_modules && time npm install
npm install  202.59s user 26.47s system 105% cpu 3:36.52 total

[misterbyrne]

Looks like there's something in the works that might help: iarna/gauge#7 (comment)

[ghengeveld]

Same here. I'm running local-npm so I can rule out any network related issues:

npm set progress=false && rm -rf node_modules && time npm install
npm install  145.31s user 27.80s system 80% cpu 3:34.27 total

npm set progress=true && rm -rf node_modules && time npm install
npm install  302.40s user 27.31s system 101% cpu 5:25.79 total

That's a 41% increase in total time.

[vysinsky]

Same here npm 3.3.12, Linux Mint 17.3 Cinnamon

npm set progress=true
rm -rf node_modules
time npm install
npm install  286,70s user 28,54s system 80% cpu 6:31,36 total

npm set progress=false
rm -rf node_modules
time npm install
npm install  137,00s user 24,83s system 73% cpu 3:41,31 total

Computer specs:

• Lenovo IdeaPad Flex 15
• Intel Core i5-4200U
• 8 GB RAM
• SSD

[Reinmar]

Minor difference in my case: https://gist.github.com/Reinmar/f69303b79157f2ca5764 (npm 3.5.2, MacOS) and here.

Maybe it's OS specific?

[AgronKabashi]

Keep in mind that this is most likely also affected by the user's machine specs. The diff might be notably higher on lower end computers.

[GavinJoyce]

The diff might be notably higher on lower end computers.

I'm running OSX 10.11.2 / MacBook Pro 2015

[dashdanw]

@AgronKabashi i'm sure the slowdown would still be rationally similar. Seems like regardless of how slow the system is, most are experiencing something around a 2x slowdown.

[timdorr]

What terminal app do you use and what font do you have selected? Also, do you have anti-aliasing enabled in your terminal?

The system might be using a fallback font for rendering the progress bar, since most "nice" programming fonts don't have line glyphs that the progress bar uses. That could be slowing things down.

Also, AA or other fancy graphical things (transparent windows) can slow down draw commands. I'd make sure your terminal is up to date or try a nightly build if it's iTerm.

[GavinJoyce]

I use iTerm2 Build 2.1.4 with a zsh shell. Here is my config:

[timdorr]

I'd be curious to see a performance measurement with non-ascii anti-aliasing disabled. I suspect this is slow draw performance.

[flying-sheep]

reddit thinks it’s IO

[timdorr]

Here's my diff:

progress=false

real    1m18.456s
user    0m27.572s
sys 0m7.639s

progress=true

real    1m23.974s
user    0m40.056s
sys 0m7.364s

I'm running Inconsolata-dz for Powerline with regular anti-aliasing and non-ascii anti-aliasing disabled.

To maintain parity, here are the tests with Monaco 12pt with AA on for all fonts and a transparent window:

progress=false

real    0m51.885s
user    0m25.604s
sys 0m6.944s

progress=true

real    1m9.172s
user    0m38.643s
sys 0m7.226s

Some difference, but not huge. I wonder if someone can run it with node --prof somehow and get a profiler dump to analyze.

[lipis]

Regardless of progress bar.. npm is super slow!!

[uhoh-itsmaciek]

For what it's worth, I seem to be affected by this as well:

progress=false

$ time npm install
...
real    1m30.147s
user    1m2.716s
sys 0m5.052s

$ time npm install
...
real    1m17.472s
user    0m58.336s
sys 0m4.484s

$ time npm install
...
real    1m20.335s
user    1m1.436s
sys 0m4.976s

progress=true

$ time npm install
...
real    2m35.531s
user    2m11.340s
sys 0m5.628s

$ time npm install
...
real    2m23.303s
user    2m4.780s
sys 0m5.396s

$ time npm install
...
real    2m21.438s
user    2m2.048s
sys 0m4.880s

I'm on Ubuntu 15.04, GNOME Terminal 3.14.2, with the default font.

[Fishrock123]

npm appears to be working on it in iarna/gauge#7

[gcoguiec]

If my modest benchmarks can help in some way:

sw_vers -productVersion

10.11.3

system_profiler SPHardwareDataType | grep Model

Model Name: MacBook Pro
Model Identifier: MacBookPro11,4

node -v

v5.5.0

npm -v

3.6.0

rm -rf ~/.npm && rm -rf node_modules is executed for every following command:

npm install --progress=false  48.69s user 17.32s system 97% cpu 1:07.64 total
npm install --progress=true  79.44s user 17.81s system 107% cpu 1:30.77 total
npm install --progress=false --loglevel=info  50.37s user 17.66s system 104% cpu 1:05.12 total
npm install --progress=true --loglevel=silent  72.52s user 16.71s system 109% cpu 1:21.18 tota

I'm using iTerm 2.1.4 with Droid Sans Mono font.

[samccone]

TL;DR

Installing without the progress bar on npm causes a 20% speedup to overall install time. The slowdown is due to a hot method call that if throttled, would prevent the majority of the slowdown.

---

Over the past few days or so, there have been some interesting comments on twitter around npm’s progress bar and the performance cost of having it enabled.

Instead of just blindly throwing conclusions only based on running time npm i, I decided to take a look at the cpu profile of the process using my handy fork of npm with instrumentation baked in https://github.com/samccone/npm/tree/sjs/profiler

On a cold run with a prewarmed .npm cache folder from an earlier install, I am seeing a 20% increase in the install time .. from npm i to process exit.

With Progress

Without Progress

Stepping down into the bottom up view of the cpu profiler in chrome devtools right away we can verify exactly what is eating up that 20%

With tracker on:

With tracker off:

Hmm so when the progress bar is enabled it looks like 23~% of the program time is being spent in a method called TrackerGroup.completed inside of the are-we-there-yet module… Let's take a closer look at exactly what is going on there

Taking a look in Cachegrind via https://github.com/jlfwong/chrome2calltree allows us to even further visulize the sheer cost of the progress bar during runtime

^ That big red blob is time spent inside of the logging

So there seems to be 3 players in progress bar game here:

Gauge https://github.com/iarna/gauge/blob/master/progress-bar.js
Are-we-there-yet https://www.npmjs.com/package/are-we-there-yet
Npmlog https://github.com/npm/npmlog/blob/master/log.js

The question is what is causing so much time to be spent in the log methods.

So then let’s look at showProgress

Alright, so it looks like we are totally skipping it if progress has been disabled.. So let’s take one more step into the gauge show code:

Well this seems to be the issue and the reason for the massive slowdown, although there is some throttling happening inside of the ProgressBar code, we are still calling into it a lot and doing quite a bit of work before we eager exit. By simplifying the logic in the method, removing the inline method definition (which is probably causing v8 to do some extra work due to scope variable binding) and upstreaming the throttling responsibility, I believe that the cost of showing the progress bar can be significantly cut down.

[SomeKittens]

Jumping into this conversation, (I'm "SomeKittens", not just "Kittens"). I tried a few different packages and got different results (though I was able to repro the timings with react-native). Trying with my own package (https://github.com/SomeKittens/gustav), I actually saw an improvement with the progress bar (though my methodology there is slightly different, I didn't rm -r ~/.npm/). I can re-run the benchmark when I get home tonight.

https://gist.github.com/SomeKittens/aee7b945f413333fb049

[othiym23]

Just a quick note to say that the CLI team is aware of this issue, and after @samccone's in-depth analysis (for which: thank you very much), much further contribution to the thread is likely to just be piling on.

[Morantron]

Nice profiling tools! Noting them down 📝

[reimertz]

@samccone That is some legit detective work. I 🙇 to you sir.

[rauchg]

Awesome analysis as usual @samccone. Thank you

[iarna]

TBH I'm a bit embarrassed that I didn't push out a quick gauge patch earlier. I've been aware of this as an issue for a while and the fix was literally 10 minutes or so of effort, but it hadn't bubbled up in priority as I hadn't realized how big an impact it was having. I'd been waiting as it's addressed by the improved architecture of the rewrite (prints at a set interval, no debounce needed), but clearly it was worth doing sooner than later.

[rauchg]

@iarna no need to be embarrassed. This only surfaced due to its immense popularity ✌️

[watilde]

I read codes and a forEach loop may be called every EE.on.('change', func):

1. https://github.com/npm/npmlog/blob/master/log.js#L54
2. https://github.com/npm/npmlog/blob/master/log.js#L105
3. https://github.com/iarna/are-we-there-yet/blob/master/index.js#L26-L28

[techmaurice]

Thanks, @samccone !

[jrudolph]

FWIW I created an interactive flame graph (built using the instructions from here):

Clicking on the the link will open an SVG that allows to drill down into more information. The big bars are TrackerGroup.completed as @samccone has found out as well. I wonder if one reason for the slowness is that this completed call will recompute its value by traversing the whole tree for each invocation anew. A more reasonable strategy could be to propagate work done from the leaves to the root of the tree and caching the value at each node instead of re-traversing the whole tree for every query of completed. (Not querying the value so often in the first place as suggested by @samccone is, of course, a good idea as well)

UPDATED: removed the inline svg

[STRML]

I've opened three PRs based on profiling I've done motivated by this ticket.

1. npmlog: Add throttling - this will allow npm to easily throttle calls to showProgress at a reasonable tick rate.
2. npmlog: Mix methods into prototype Another reasonably hot function was mixinLog, which doesn't need to be called on every creation of a TrackerGroup - it can simply mix the functions into TrackerGroup.prototype
3. npm: Use fast JSON clone instead of _.cloneDeep() - After throttling the progress bar, the next heaviest item in the profile was defensive cloneDeeps after removing some properties from JSON package descriptors. Since these are JSON (and don't include Dates, for instance), it's safe to clone them this way.

These three updates have gotten an npm install of loopback (with devDeps) from just over 3min to about 1:50.

We can do further easy optimization by moving to EventEmitter3 for most (maybe all) uses of EventEmitter, as the built-in Node emitter actually causes deopt quite often.

Other optimization possibilities are possible inside are-we-there-yet, including memoizing repeated work as @jrudolph has mentioned.

[STRML]

For reference:

Before:

After (throttling of 100ms + above perf tweaks):

Given the amount of GC pressure here (although much improved) I would expect there's deopt somewhere we're missing. My suspicion is in the EventEmitter.

[samccone]

impressive work @STRML 👏 🎩

[STRML]

Got another PR to are-we-there-yet:

This gets our CPU usage down another 100x compared to the last patch.

Performance on this patch is a little crazy - without throttling on npm's side, I only get about 2x, not 100x (roughly 61 seconds down to 27). With throttling, it appears to hit some optimization sweet spot and CPU cost is only 64ms.

So that's 61113ms -> 64ms!

[jadbox]

@STRML 100x is pretty impressive. What was the core issue here? Was it really the inline functions + forEach causing that much overhead versus switching to the for statement?

Perhaps try turning the closure into a function definition instead instead of resorting to raw for statements. Might even try to give this babel plugin a shot to auto convert your inline closures: https://github.com/codemix/babel-plugin-closure-elimination

[STRML]

@jadbox Would much rather just use a for loop than introduce Babel into the toolchain of a simple module - but nice link! I may use that in some personal projects.

The bulk of the gain appears to be from removing the forEach loop. Might have something to do with how deep the call chain gets causing an opt bailout. Appears the bind tweak at the top of the file does about 50% as well.

[samccone]

cc @indutny for some v8 depot insights ^

[indutny]

@samccone TL;DR ? Has anyone actually run code with --trace-deopt to see what in particular is being deoptimized? Is deoptimization really connected to GC time, I have never seen this before.

[Sinewyk]

@jrudolph I suspect that your SVG inlined is making our browsers work a lot for nothing much, most of us who actually want to see something will click on it ... so you should probably remove the inlining and just put a link to it to relieve our browsers.

Or just take a screenshot and you can inline this.

[STRML]

@indutny I'm incorrect on that, the Chrome profiler doesn't report GC time as function's self time even if the GC happens during that execution; something else is going on.

Re: tracing deopt, I've run most of the relevant code; aside from a small deopt in EventEmitter#emit I haven't seen anything else of consequence.

[tracker1]

@STRML What's the memory footprint look like for a large-ish npm install?

Just curious, on a project last year, I found that forcing GC every N cycles through a stream kept the memory footprint pretty low, which helped in our test deploy with was a resource constrained system.

[paulirish]

I'm incorrect on that, the Chrome profiler doesn't report GC time as function's self time even if the GC happens during that execution; something else is going on.

Not sure about that. Might be true for MajorGC, but IncrementalMarking etc may be included in the self-time right now.

[Krinkle]

I've got npm install & npm test under a short cut to trigger test runs. It used to run the install part just for a split second (if nothing changed) before the tests commence. But since npm 3 it's always taking 10-20 seconds to iterate over all the packages. About as much time as it takes to do a fresh install after deleting node_modules. If I didn't know better, I'd think npm 3 decided to no longer re-use local installs and always install everything fresh.

However, confirmed that setting npm set progress=false changed it back to normal speed. (using npm 3.7.5; node v5.5.0)

[Webysther]

My stats with node v5.10.1

npm set progress=false && rm -rf ~/.npm && rm -rf node_modules && time npm install

real    3m33.941s
user    1m40.416s
sys 0m20.864s

npm set progress=true && rm -rf ~/.npm && rm -rf node_modules && time npm install

real    3m40.210s
user    1m23.640s
sys 0m13.956s

npm set progress=false && rm -rf node_modules && time npm install

real    2m10.048s
user    1m15.416s
sys 0m12.492s

npm set progress=true && rm -rf node_modules && time npm install

real    2m25.098s
user    1m23.788s
sys 0m14.460s

npm set progress=false  && time npm rebuild

real    0m11.728s
user    0m11.140s
sys 0m1.340s

npm set progress=true  && time npm rebuild

real    0m12.364s
user    0m11.732s
sys 0m1.244s

[brandonweiss]

Is this still an issue?

[Webysther]

apparently all ok

[BookOfGreg]

Node v5.10.1

npm set progress=true && rm -rf ~/.npm && rm -rf node_modules && time npm install
real    4m8.986s
user    2m9.952s
sys 0m44.503s

npm set progress=false && rm -rf ~/.npm && rm -rf node_modules && time npm install
real    3m53.351s
user    2m0.788s
sys 0m39.196s

There still is a difference, and it's slower for progress=false but faster for progress=true than it was on Node 4.1.1, It's down to about 6% difference between progress for me on the same deps as my previous comment on Node 4.1.1
Not sure what changed but much closer than it used to be.

[Sinewyk]

As long as it's ~5% that's ok IMO. Start of issue was ~40-50% performance degradation.

You can't expect additional work (tracking of progress) to have 0 impact on performance, so the slight degradation is expected.

consider this fixed and close it ?

[ahmadawais]

@BookOfGreg @Webysther The latest stable version of node is 4.4.5 do you recommend using the latest one E.g. v6 to avoid this issue?

[iarna]

@Sinewyk I'm landing a rewrite of the progress bar this week that will likely eliminate even that 5%, so my plan was to close this when that lands.

[ahmadawais]

@iarna That rewrite will be part of which NPM version?

[kevinSuttle]

Is it possible to set progress=false inside package.json?

[jffry]

@kevinSuttle You can put progress=false (or any other npm config) inside a file named .npmrc in the same folder as your package.json ; see https://docs.npmjs.com/files/npmrc for details on .npmrc

[iarna]

I'm closing this because we landed the updated gauge ages in v3.10.0, way back in June, and there shouldn't be any more progress bar related slow downs. (It prints at a fixed interval now, so printing it shouldn't be adding a measurable amount of work.)