Nvm: Loading nvm is unbelievably slow (7-46 seconds)

[polybuildr]

I've been using nvm for quite some time now and I recently installed it on a new laptop running Ubuntu 16.04. I've been experiencing extremely high load times: between 7 and 46 seconds on both zsh (my primary shell) as well as bash.

Here's the output of nvm debug (I had chsh-ed to try bash):

nvm --version: v0.32.0
$SHELL: /bin/bash
$HOME: /home/vivek
$NVM_DIR: '$HOME/.nvm'
$PREFIX: ''
$NPM_CONFIG_PREFIX: ''
nvm current: v6.7.0
which node: $NVM_DIR/versions/node/v6.7.0/bin/node
which iojs: iojs not found
which npm: $NVM_DIR/versions/node/v6.7.0/bin/npm
npm config get prefix: $NVM_DIR/versions/node/v6.7.0
npm root -g: $NVM_DIR/versions/node/v6.7.0/lib/node_modules

I tried rm -rf ~/.nvm and reinstalled, but there was no improvement. I downgraded to 0.31.7 and saw some improvement - most load times were around 7 seconds now.

Please let me know whether there are some additional debugging steps that might help - I really can't believe that loading nvm could be this slow without something messing around!

[ljharb]

Try changing the line in your profile that sources nvm to something like . "$NVM_DIR/nvm.sh" --no-use - does that speed it up?

[polybuildr]

Yep, nvm use is the culprit. After the sub-second source, running nvm use default took a full 47 seconds!

[polybuildr]

Is there a local workaround solution to this issue? Or is it just something that nvm will have to fix?

[ljharb]

I'm not aware of a workaround, since I'm still not sure why it's particularly slow. npm config get prefix is the slowest part of nvm use, but it usually adds 400ms, while the rest of the command takes another 400ms - it wouldn't explain 7 seconds.

[polybuildr]

What's interesting is that this only happens the first time I load nvm after boot. All future loads in other terminal tabs are pretty fast, about ~1 second. What's different the first time it loads?

[ljharb]

Hmm, that's a good question. I wonder if your filesystem is caching things (like what's inside $NVM_DIR, or something)?

[polybuildr]

Any ideas on how I could check whether it's doing that? $NVM_DIR is about 390 MB in size, though, so it definitely can't be caching all of it.

Also, is there a good way for me to profile each step in the loading process? I could put a set -v and change my PS4 to echo the time, but any better way? Maybe I can confirm what causes the slowdown on my system.

[ljharb]

I was thinking it cached the directory listing (not the contents), but I have no idea.

I know that zsh offers profiling like that, but I've no idea how to use it :-/ If you can figure out some profiling that would help a ton.

[polybuildr]

Right, that definitely makes more sense. :P

I'm busy the next couple of days, but after that, I'll try to profile stuff and let you know how that goes.

[polybuildr]

Last boot, loading nvm took about 8 seconds. I ran zmodload zsh/zprof before loading nvm, and then ran zprof to get the profiling output. The results are in a gist here: https://gist.github.com/polybuildr/26d7fafdac767b8c9a83d5a9de509260

I haven't analyzed the output much yet (will try again in a couple of days), but just the zprof output might be useful.

[ljharb]

@polybuildr thanks! As expected, nvm_die_on_prefix takes the most time (because it's calling npm config get prefix). It does, however, seem like that's called more times than it should be - I'm not sure how to read zprof output. Can you clarify which lines constitute distinct calls into nvm_die_on_prefix?

[polybuildr]

As far as I can tell from the zprof output, it looks like it only gets called once every time (from the "calls" column). I tried to see - crudely - how many seconds the npm config get prefix call takes:

Called 'npm config get prefix'...
Thu Oct 27 16:04:03 IST 2016
Thu Oct 27 16:04:03 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 16:04:03 IST 2016
Thu Oct 27 16:04:04 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 17:05:21 IST 2016
Thu Oct 27 17:05:21 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 17:31:20 IST 2016
Thu Oct 27 17:31:21 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 18:32:09 IST 2016
Thu Oct 27 18:32:09 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 19:30:57 IST 2016
Thu Oct 27 19:30:58 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 19:57:00 IST 2016
Thu Oct 27 19:57:00 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 20:30:07 IST 2016
Thu Oct 27 20:30:08 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 20:56:59 IST 2016
Thu Oct 27 20:57:00 IST 2016
Called!
Called 'npm config get prefix'...
Thu Oct 27 23:38:57 IST 2016
Thu Oct 27 23:39:06 IST 2016
Called!

Mostly 1 or 2 seconds, but sometimes ~9 seconds. Any idea why this drastic variation? Also, are there any other possible culprits than npm config get prefix that I should specifically look into?

[ljharb]

I'm not sure why there's variation - it's all internal to npm.

Other than that, there's calls into nvm_ls (via nvm_version via nvm_ensure_version_installed) that are probably also slowing things down.

[polybuildr]

Last boot, the load time was 70 seconds :disappointed: I did another zprof and got this: https://gist.github.com/polybuildr/9aeb92664146a289383f9e19a9a57089

So whatever it is, it definitely happens inside nvm_die_on_prefix. The log for tracking npm config get prefix showed:

Called 'npm config get prefix'...
Fri Oct 28 10:35:05 IST 2016
Fri Oct 28 10:36:15 IST 2016
Called!

So, while there are some other issues, this is definitely the whopper. As a workaround, I've simply hardcoded my current version's npm prefix where nvm.sh makes the call to npm. I tend to use the same version of node everywhere, so until I update, this shouldn't cause any problems, should it?

Additionally, I think I should also file a bug in npm - 70 seconds just seems crazy!

[ljharb]

@polybuildr filing an issue in npm would be great, and yes, hardcoding that won't break as long as when you update, you use the normal install script, and as long as you never set the "prefix" config :-)

[polybuildr]

I've filed the issue at npm/npm#14458.

[polybuildr]

Oh and thanks a lot for confirming that this hardcoding solution will work for now! :)

[dotnetCarpenter]

I'm also experiencing incredible slow load time for NVM.

real    0m11.387s
user    0m1.308s
sys 0m0.608s

Timing . "$NVM_DIR/nvm.sh"

I'm trying to understand the work-around - where exactly do I write the node version?

[nylen]

I added a bunch of debug info to find the slow parts of nvm initialization on a small embedded system (Raspberry Pi-like) and most of the slow load time is due to the two times that npm is called during nvm use. Once for npm --version and once for npm config --loglevel=warn get prefix.

If I want to know what the npm version is, I can just run npm --version myself (and wait about 3 seconds on a good day when caches are nicely primed).

I don't understand exactly what nvm_die_on_prefix is doing but it seems like I can safely skip this entire function on shell init at least.

@ljharb what do you think about skipping these two calls to npm on shell init, perhaps with environment variables to opt in, like NVM_SKIP_NPM_VERSION and NVM_SKIP_PREFIX_CHECKS? Under what situations is it actually necessary to call nvm_die_on_prefix?

The next slowest portion of init is nvm_resolve_local_alias default, so it might also be a good idea to be able to specify an exact version to use on init.

[ljharb]

@nylen you're quite right that the npm invocations are what's slowing everything down. You can use --silent on most commands and it will skip the npm --version call, but that's not really slow anyways - npm config get prefix is.

And no, I will not allow any way to skip the prefix checks; it's necessary on every single call to nvm use.

[nylen]

Ok, can you explain a bit about what the prefix checks are actually doing?

[ljharb]

Sure. The prefix is what determines npm root -g, ie, where npm installs global modules and links. nvm requires that location be inside its own version dirs, and is incompatible with that setting.

Many people have it set from following ill-advised tutorials, for example. By adding these checks, a very very large number of monthly bug reports stopped coming in.

Basically, it's doing npm config get prefix, and then if that location isn't inside the nvm version dir, it errors out.

[nylen]

On this small machine I'm using, npm --version is just about as slow as npm config get prefix (3 seconds from a well-primed cache, details at https://github.com/npm/npm/issues/14458#issuecomment-366882873). nvm_resolve_local_alias default is not far behind at about 1.5 seconds.

I would still like a way to skip as many of those three phases as possible (npm --version, npm config get prefix, and nvm_resolve_local_alias default). I'm happy to submit PRs if we can agree on a general approach.

[ljharb]

• nvm use --silent whatever will skip the version call; the auto-use-on-source logic already passes --silent.
• the "default" resolution only happens when an explicit version is not provided, or with auto-use-on-source.
• the auto-use-on-source logic can be bypassed by changing the sourcing line in your profile file to have --no-use at the end

[nylen]

• You're right, I removed --silent from this code path while adding debug info, so this was a bug I introduced. The call to npm --version is gone, though it will still happen (IMO unnecessarily) if I do nvm use manually.
• _the "default" resolution happens with auto-use-on-source_ - I'd like to be able to skip this. I know what the default version of node is on this system and I'm fine with specifying that manually.
• _the auto-use-on-source logic can be bypassed_ - This is true, but I only have node installed through nvm (no system version) because that's by far the most convenient way to do it. So doing this defeats much of the point of using nvm.

[ljharb]

nvm_resolve_local_alias default is basically just cat-ing a file; i'm pretty surprised that's a slow operation on any system. If you can think of ways to speed up alias resolution, I'm all for it.

[nylen]

The approach in https://github.com/creationix/nvm/pull/1737 works well for me.

[nylen]

https://github.com/nylen/dotfiles/commit/33bb4a8332aff88ed7d74584b7bc2a9225f79deb / https://github.com/nylen/dotfiles/commit/cdb850873823bacc1662220b8e276c06f58fc6f1 also works for me and doesn't require any modifications to nvm code.

Before these changes, initializing nvm takes about 6 seconds on a primed page cache and 15 seconds on a non-primed cache. After, 1 second and 3 seconds respectively _[edit: fixed measurements]_.

For me, personally, the performance improvement is dramatic and well worth the trade-offs.

[daxxog]

I made a dynamic NVM loader to speed things up. This way we don't run the NVM loader code every time we open a new terminal window.

#!/bin/zsh
# ~/loadnvm.sh

#delete the aliases
unalias nvm
unalias npm
unalias node

#(this is the loader code nvm put in my .bashrc)
export NVM_DIR="$HOME/.nvm"
[ -s "$NVM_DIR/nvm.sh" ] && \. "$NVM_DIR/nvm.sh"  # This loads nvm
[ -s "$NVM_DIR/bash_completion" ] && \. "$NVM_DIR/bash_completion"  # This loads nvm bash_completion

and then in .zshrc (or .bashrc)

# nvm
alias nvm='. ~/loadnvm.sh; nvm "$@"'
alias npm='. ~/loadnvm.sh; npm "$@"'
alias node='. ~/loadnvm.sh; node "$@"'

You could even put this script in your .nvm directory if you don't want it cluttering your $HOME.

EDIT: I added aliases for npm and node as well

[ljharb]

Don't forget npx, and all the global packages installed in your default node version. Also iojs if it's v1-v3.

[king-11]

So I am now using this code snippet and it has really used my startup time in zsh shell while ensuring that I also have access to global packages as well as yarn globals and yarn project have same node env version. Would like to know if it works for others as well.

```zsh
export NVM_DIR="$HOME/.nvm"

[ -s "$NVM_DIR/nvm.sh" ] && . "$NVM_DIR/nvm.sh" # This loads nvm

[ -s "$NVM_DIR/bash_completion" ] && . "$NVM_DIR/bash_completion" # This loads nvm bash_completion

NODE_GLOBALS=(find ~/.nvm/versions/node -maxdepth 3 -type l -wholename '*/bin/*' | xargs -n1 basename | sort | uniq)
NODE_GLOBALS+=(node nvm yarn)

_load_nvm() {
[ -s "$NVM_DIR/nvm.sh" ] && . "$NVM_DIR/nvm.sh"
[ -s "$NVM_DIR/bash_completion" ] && . "$NVM_DIR/bash_completion" # This loads nvm bash_completion
}

for cmd in "${NODE_GLOBALS[@]}"; do
eval "function ${cmd}(){ unset -f ${NODE_GLOBALS[*]}; _load_nvm; unset -f _load_nvm; ${cmd} \$@; }"
done
unset cmd NODE_GLOBALS

export PATH="$PATH:$HOME/.yarn/bin"```