New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Loading nvm is unbelievably slow (7-46 seconds) #1261

Open
polybuildr opened this Issue Oct 12, 2016 · 28 comments

Comments

Projects
None yet
4 participants
@polybuildr

polybuildr commented Oct 12, 2016

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

This comment has been minimized.

Collaborator

ljharb commented Oct 12, 2016

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

This comment has been minimized.

polybuildr commented Oct 12, 2016

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

@polybuildr

This comment has been minimized.

polybuildr commented Oct 17, 2016

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

@ljharb

This comment has been minimized.

Collaborator

ljharb commented Oct 18, 2016

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

This comment has been minimized.

polybuildr commented Oct 18, 2016

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

This comment has been minimized.

Collaborator

ljharb commented Oct 18, 2016

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

@polybuildr

This comment has been minimized.

polybuildr commented Oct 18, 2016

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

This comment has been minimized.

Collaborator

ljharb commented Oct 18, 2016

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

This comment has been minimized.

polybuildr commented Oct 18, 2016

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

This comment has been minimized.

polybuildr commented Oct 23, 2016

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

This comment has been minimized.

Collaborator

ljharb commented Oct 23, 2016

@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

This comment has been minimized.

polybuildr commented Oct 27, 2016

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

This comment has been minimized.

Collaborator

ljharb commented Oct 27, 2016

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

This comment has been minimized.

polybuildr commented Oct 28, 2016

Last boot, the load time was 70 seconds 😞 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

This comment has been minimized.

Collaborator

ljharb commented Oct 28, 2016

@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

This comment has been minimized.

polybuildr commented Oct 28, 2016

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

@polybuildr

This comment has been minimized.

polybuildr commented Oct 28, 2016

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

@dotnetCarpenter

This comment has been minimized.

dotnetCarpenter commented Mar 21, 2017

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

This comment has been minimized.

nylen commented Feb 20, 2018

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

This comment has been minimized.

Collaborator

ljharb commented Feb 20, 2018

@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

This comment has been minimized.

nylen commented Feb 20, 2018

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

@ljharb

This comment has been minimized.

Collaborator

ljharb commented Feb 20, 2018

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

This comment has been minimized.

nylen commented Feb 20, 2018

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 npm/npm#14458 (comment)). 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

This comment has been minimized.

Collaborator

ljharb commented Feb 20, 2018

  • 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

This comment has been minimized.

nylen commented Feb 20, 2018

  • 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

This comment has been minimized.

Collaborator

ljharb commented Feb 20, 2018

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

This comment has been minimized.

nylen commented Feb 20, 2018

The approach in #1737 works well for me.

@nylen

This comment has been minimized.

nylen commented Feb 20, 2018

https://github.com/nylen/dotfiles/commits/master 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment