Shell startup can be improved by not printing npm version when sourcing nvm.sh

[alanmquach]

I found that the slowest part (0.5s, so not horrible) of my shell startup was sourcing nvm.sh so out of curiosity, I dove in to see what it was spending all it's time doing.

While considerable time is spent in:

• nvm_version
• nvm_ensure_version_installed

They're at least doing useful work. Also nvm_ensure_version_installed has already been flagged as a possible optimization.

I almost overlooked the echo statements at the end but found that nvm_print_npm_version takes just as much time as the heavy hitters above, all just to print the npm version (presumably because it calls out to npm --version). Moreover, while this might be useful info, it certainly isn't when it gets >/dev/nulled as it does in the shell startup case.

Opened #780 for this. Not sure if it's the cleanest but that's the idea. I'd be happy to implement it in a cleaner way needed.

[alanmquach]

Also some data points that I'm quite pleased with:

Before

( source ~/.nvm/nvm.sh; )  0.35s user 0.36s system 105% cpu 0.676 total
( source ~/.nvm/nvm.sh; )  0.33s user 0.31s system 115% cpu 0.551 total
( source ~/.nvm/nvm.sh; )  0.33s user 0.32s system 114% cpu 0.575 total
( source ~/.nvm/nvm.sh; )  0.33s user 0.32s system 115% cpu 0.565 total
( source ~/.nvm/nvm.sh; )  0.33s user 0.34s system 112% cpu 0.599 total

After

( source ~/.nvm/nvm.sh; )  0.16s user 0.30s system 122% cpu 0.368 total
( source ~/.nvm/nvm.sh; )  0.15s user 0.29s system 123% cpu 0.354 total
( source ~/.nvm/nvm.sh; )  0.15s user 0.29s system 124% cpu 0.356 total
( source ~/.nvm/nvm.sh; )  0.15s user 0.28s system 124% cpu 0.341 total
( source ~/.nvm/nvm.sh; )  0.15s user 0.28s system 124% cpu 0.343 total

[jottr]

I am removing nvm from my shell for the time being, since it is currently adding too much lag when spawning a new shell.
@alanmquach that's a great catch. How did you profile the time to source nvm.sh?

[ljharb]

@jottr do you use oh-my-zsh? So far all the reports of slowness have been specific to omz users - I suspect a conflict between one of the opts omz sets, and one of the commands nvm is running.

I'll be merging #780 soon which should help a lot (thanks @alanmquach for that)

[jottr]

@ljharb yes, I am using omz.

[alanmquach]

@jottr trusty ol' time. I dove into the code branches that execute when nvm.sh is sourced and just wrapped random things in time() to roughly determine where time was spent.

@ljharb FWIW, I'm using omz as well but times are mostly the same (for me) between bash, omz, and plain zsh. Note that I just refreshed my machine so my nvm is really simple:
default -> stable -> v0.12.7.

[ljharb]

@alanmquach hmm, what OS are you using?

[alanmquach]

@ljharb OSX Yosemite on a MacBook Pro 2.9Ghz i5

[ljharb]

@alanmquach Can you gist me your profile files? I have a similar setup and have never run into trouble.

[alanmquach]

@ljharb You can take a look at (or even source) my dotfiles. How long does it take you to source ~/.nvm/nvm.sh? 0.5 is by no means slow. It was just instant without nvm and barely noticable with.

[ljharb]

@alanmquach in bash, if you comment out those shopt lines, does nvm get faster for you?

Because nvm is sourced, it doesn't get a fresh shell with no options set, so it's very easy to break it by setting non-default options that I haven't explicitly accounted for.

[alanmquach]

@ljharb I commented out everything in my .bash_profile (so that it's pure bash, no bells or whistles) and sourcing nvm.sh is still about the same numbers as zsh and even omz.

Times are a bit faster on my Ubuntu box (running Trusty), although I did notice there was a clear regression between v0.23.3 and v0.24.0 (likely from the nvm_ensure_version_installed check?)

Just curious, how long does it take you to time (source nvm.sh)?

[ljharb]

nvm unload ; time (source ~/.nvm/nvm.sh)

real    0m0.113s
user    0m0.053s
sys     0m0.081s

[alanmquach]

Wow! OS? Hardware?

[ljharb]

OS X Yosemite, rMBP 15" 2.8GHz. I do have an SSD though, so that might be part of it.

[alanmquach]

I'm on a 2015 rMBP 13" which I think should have the new PCIe SSDs. 😕

Do you have anything special that may be speeding it up? Bash 4?

[ljharb]

I've got stock bash, 3.2.57. Have you tried commenting out those bash profile options, and actually opening a new shell, and then comparing the time? shopts often can't be unset after they're set.

[alanmquach]

Yep. I actually commented out everything. Restarted Terminal (just in case) and confirmed that those options were not set. This is quite puzzling.

What is your nvm configuration? Do you have a system node? I only have default -> stable.

The only other thing I can think of is for me to really dig into where time is being spent on my system and micro benchmark the low level operations shell operations between our systems...

[alanmquach]

Oh, also I assume you have an i7 with 2 more cores. I can try to grab some people on Monday with an i5 and an i7 for a few more data points. See if that's what it is.

[ljharb]

i7, yes. No system node, altho my previous machine did and I never ran into trouble either.

[moander]

FYI

$ nvm unload ; time (source ~/.nvm/nvm.sh)

real  0m0.276s
user  0m0.141s
sys   0m0.208s

The --silent switch speeds things up considerably:

$ nvm version ; time nvm use --silent 0.12.7 ; time nvm use --silent 4.1.0 

v4.1.0

real  0m0.086s
user  0m0.036s
sys   0m0.060s

real  0m0.088s
user  0m0.037s
sys   0m0.063s

$ nvm version ; time nvm use 0.12.7

v4.1.0
Now using node v0.12.7 (npm v2.11.3)

real  0m0.258s
user  0m0.186s
sys   0m0.085s

npm calls seems to be slow whatever sub-command you use

$ time npm>/dev/null ; time npm --version>/dev/null

real  0m0.308s
user  0m0.279s
sys   0m0.035s

real  0m0.216s
user  0m0.189s
sys   0m0.028s

I'm on a MacBook Pro:
2.8GHz Quad-core Intel Core i7, Turbo Boost up to 4.0GHz
16GB 1600MHz DDR3L SDRAM
1TB PCIe-based Flash Storage

$ uname -mprs ; nvm --version ; which npm ; bash --version
Darwin 14.5.0 x86_64 i386
0.26.1
/Users/moander/.nvm/versions/node/v4.1.0/bin/npm
GNU bash, version 3.2.57(1)-release (x86_64-apple-darwin14)

[totallymike]

Performance isn't so hot for me either. My machine characteristics are similar to @moander's, but with less RAM.

Here's the outcome of sourcing nvm.sh on my (vanilla) bash shell.

bash-3.2$ time ( source ~/.nvm/nvm.sh; )

real    0m0.530s
user    0m0.407s
sys 0m0.148s

uname -mprs; nvm --version; which npm; bash --version
Darwin 15.0.0 x86_64 i386
0.29.0
/Users/mwestbom/.nvm/versions/node/v4.1.2/bin/npm
GNU bash, version 3.2.57(1)-release (x86_64-apple-darwin15)
Copyright (C) 2007 Free Software Foundation, Inc.

Here's a gist with the output of zprof when sourcing nvm.sh as collected by:

# unload NVM; reset profiler; reload NVM; dump prof
nvm unload; zprof -c; source ~/.nvm/nvm.sh; zprof > nvm-prof.txt

https://gist.github.com/totallymike/856c80bca85087df55af

For reference, here's what the docs say about zprof output

At the top there is a summary listing all functions that were called at least once. This summary is sorted in decreasing order of the amount of time spent in each. The lines contain the number of the function in order, which is used in other parts of the list in suffixes of the form ‘[num]’, then the number of calls made to the function. The next three columns list the time in milliseconds spent in the function and its descendants, the average time in milliseconds spent in the function and its descendants per call and the percentage of time spent in all shell functions used in this function and its descendants. The following three columns give the same information, but counting only the time spent in the function itself. The final column shows the name of the function.

[moander]

Here is a dirty workaround to the terminal startup annoyance.

.bash_profile:

export PATH=$HOME/.nvm/versions/node/v5.4.0/bin:$PATH
alias nvm='unalias nvm ; . ~/.nvm/nvm.sh && . ~/.nvm/bash_completion &&  nvm'

Replace v5.4.0 to with your preferred default node version :)

[ljharb]

It's very unwise to bake a hardcoded path into your profile file. In addition, that will mean nvm bash completion will be unavailable until you've invoked nvm.

[moander]

It depends on individual usage patterns. I'm opening new terminals all the time.. Say 200 times a day in average. That adds up to one full hour of waiting time each month.. So I can not support your claim that it is unwise to instead having to type nvm for it to fully enable bash completion for the rest of terminal lifetime.

It's simple math. If you open a terminal more often than you need nvm bash completion you are better off with lazy loading. (my opinion) :)

[eladnava]

@moander I completely agree with you.

I was wondering why my terminal was starting up so slowly, even with an SSD. It would take around ~800ms to load, which is a buzzkill.

Now I can just invoke nvm when I need it and avoid loading it for every terminal session. By the way, I didn't need to append the nvm path to the PATH environment variable. All I needed was the alias command.

[alanmquach]

I think the culprit is the npm config get prefix call, as noted in #966 .

Which is a huge bummer because now every new terminal is running a node process that interprets and executes npm, and even running just npm without any other actions takes hundreds of ms for me:

$ time npm > /dev/null

real    0m0.529s
user    0m0.380s
sys 0m0.102s

[ljharb]

That check is critical, but I'm always open to PRs to speed it up. Sadly the logic npm uses to get that config item is very complex.

[alanmquach]

I had actually taken a look at it (the code within npm) to see what it's doing, whether it can be easily replicated it in nvm but ultimately gave up, because we wouldn't want to be reimplementing a subset of npm in nvm, since the implementation could change.

Would it be possible to fix #606 differently? Like actually adding support to nvm for prefixes?
Not sure what that would entail and there's a ton of issues linked out from that one. Really just asking if you had hit any walls before I start poking around.

[ljharb]

It's more that the concept of an npm prefix is tightly coupled to the concept of their being one version of npm - it just doesn't make any sense to use it.

What might make sense is storing global modules elsewhere - but that's a lot of complexity just for nvm to have to manage a different directory.

[Tuxdude]

Is there any update on this ? I'm running into slow startup times especially when I start tmux. I usually spawn like 30 different shells in tmux, and everytime I start a new tmux session, I hit this issue.

It has actually been worse on my Linux box than Mac.

[ljharb]

@alanmquach if you want to check out the latest version of nvm, and rerun your profiling, I'd love to hear your results. The npm config get prefix call is still there, and will still be the slowest part, but I'll do what I can to speed up any other places!

[alanmquach]

@ljharb here are my current timings on v0.31.2, but I'm on a different machine (similar hardware profile) than before.

$ nvm unload ; time (source ~/.nvm/nvm.sh)

real    0m0.688s
user    0m0.421s
sys 0m0.337s

Might also be worth noting that while the hardware profile is similar to my last system, current one feels more sluggish than the last.

[Delta0001]

Glad I am not the only one having this issue. I've noticed that on slower machines (specifically my Raspberry Pi), it takes up to 8 extra seconds for my shell to start up.
Best solution for me is to disable the last two lines in .bashrc created by nvm after I finish installing the version of nodejs I need.

[eladnava]

Someone wrote a blog post about a workaround for this:
http://broken-by.me/lazy-load-nvm/?utm_source=nodeweekly&utm_medium=email

[Tuxdude]

Based on the link posted by @eladnava and the reddit link in that page (which was buggy BTW), I made a few changes and this seems to work:

# BEGIN UGLY HACK
# This lets us initialize nvm, node and any other global node binaries on demand (lazily)
# to save on shell startup time
export NVM_DIR="~/.nvm"
declare -a NODE_GLOBALS=(`find $NVM_DIR/versions/node -maxdepth 3 -type l -wholename '*/bin/*' | xargs -n1 basename | sort | uniq`)

NODE_GLOBALS+=("node")
NODE_GLOBALS+=("nvm")

# Bootstrap nvm on demand
load_nvm() {
    source "$NVM_DIR/nvm.sh"

    # (Optional) Set the version of node to use from ~/.nvmrc if available
    nvm use 2> /dev/null 1>&2 || true

    # Do not reload nvm again
    export NVM_LOADED=1
}

for node_cmd in "${NODE_GLOBALS[@]}"; do
    eval "${node_cmd}() { unset -f ${node_cmd}; [ -z \${NVM_LOADED+x} ] && load_nvm; ${node_cmd} \$@; }"
done
# END UGLY HACK

[ljharb]

@Tuxdude that will grab all node globals, including ones that are only available in a node version that isn't the default one - is that the intent?

[Tuxdude]

@ljharb - Yes I realized the script pulls globally installed binaries from all versions of node (same as what was posted on that reddit page's comments).

If there is a way to determine which version of node to use (or the default node version), we can use just that path in the find command.

[ljharb]

Sadly, I suspect that the slow part is indeed determining that.