rbenv quite slow about rbenv HOT 13 CLOSED

In the end this issue was impacting me jf/rbenv-gemset#84

from rbenv.

Here everything seems normal:

~ → time /usr/bin/ruby -v
ruby 1.8.7 (2010-01-10 patchlevel 249) [universal-darwin11.0]

real    0m0.007s
user    0m0.003s
sys 0m0.003s
~ → time ~/.rbenv/shims/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m0.048s
user    0m0.019s
sys 0m0.026s
~ → time ~/.rbenv/versions/1.9.2-p290/bin/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m0.010s
user    0m0.005s
sys 0m0.004s
~ → 

from rbenv.

→ time ~/.rbenv/versions/rbx-1.2.4/bin/ruby -v                                ~
rubinius 1.2.4 (1.8.7 release 2011-07-05 JI)
~/.rbenv/versions/rbx-1.2.4/bin/ruby -v  0.43s user 0.07s system 116% cpu 0.431 total
→ time ~/.rbenv/shims/ruby -v                                                 ~
rubinius 1.2.4 (1.8.7 release 2011-07-05 JI)
~/.rbenv/shims/ruby -v  0.45s user 0.11s system 112% cpu 0.495 total

Looks normal

from rbenv.

@fesplugas and @ingeniarius Unless I'm confused, the test should be how does a call simply to ruby (without any further specification) compare to ~/.rbenv/versions/ruby-#.#.#/bin/ruby. At least, that's the case where @cespare originally saw a big difference.

On my system (OSX Lion, MacBook Air), calls to just ruby are consistently slower (no matter what order I run the two tests, so I don't think there's any caching going on to skew results), but not nearly so much as @cespare sees (and not long enough in absolute time that I would ever care):

❯❯ time /Users/telemachus/.rbenv/versions/1.9.2-p290/bin/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m0.013s
user    0m0.007s
sys 0m0.005s
❯❯ time ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m0.162s
user    0m0.055s
sys 0m0.075s
❯❯ time ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m0.161s
user    0m0.055s
sys 0m0.075s
❯❯ time /Users/telemachus/.rbenv/versions/1.9.2-p290/bin/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m0.014s
user    0m0.007s
sys 0m0.005s

@cespare What does your PATH look like? I'm wondering if an utterly spaghetti-like PATH might account for the latency. (For example, do you have rvm and rbenv and on and on in there?)

from rbenv.

I can confirm speed differences as reported by @cespare and @telemachus. On my machine (MacBook Air), after a dozen runs: ruby -v consistently takes 0.050s to complete, while running from the expanded executable path takes 0.011s. Not much of an issue obviously, but there has to be room for improvement.

Btw, thanks for this great tool (clean, single-purpose, well thought-out, free of error-prone dead weight bells and whistles).

from rbenv.

Hmm, interesting data guys. It must be something about my particular configuration, then. I didn't have any particular slowness on a fresh vagrant box:

vagrant@lucid32:~$ time .rbenv/shims/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [i686-linux]

real    0m0.026s
user    0m0.020s
sys 0m0.008s
vagrant@lucid32:~$ time .rbenv/versions/1.9.2-p290/bin/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [i686-linux]

real    0m0.004s
user    0m0.004s
sys 0m0.000s

@telemachus However, it's not due to a big $PATH -- after trimming it down to the minimum, it's still slow:

$ echo $PATH
/Users/caleb/.rbenv/shims:/Users/caleb/.rbenv/bin:/bin:/usr/bin:/usr/local/bin/
$ time ~/.rbenv/shims/ruby -v
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]

real    0m2.530s
user    0m2.000s
sys 0m0.514s

from rbenv.

There will always be a small overhead when using rbenv's shims, but 2.5 seconds is certainly not normal.

Could you update your installation to the latest git version and run RBENV_DEBUG=1 ruby -v? This will tell rbenv to use bash's set -x option, which prints each line of code as it's executed. Perhaps you'll be able to spot a slow command or something out of the ordinary.

from rbenv.

Hey @sstephenson,

Thanks for the reply. I updated and ran the command, but it was essentially the same as when I had been debugging with echos and set -x myself before: there are a bunch of slow rbenv- operations that add up to a big overhead.

When I run RBENV_DEBUG=1 ruby -v, I get a pause and then during the printing I see distinct pauses on the following 5 lines:

+ exec /Users/caleb/.rbenv/libexec/rbenv-exec ruby -v
++ rbenv-which ruby
++ rbenv-version-name
++ rbenv-version-file
++ rbenv-version-file-read /Users/caleb/.rbenv/global

I guess that these are probably all doing one common slow operation, but I'll need to do more debugging to see.

from rbenv.

Could it be that it's just slow to spawn bash on your system? What does time /usr/bin/env bash -c exit report?

Have you tried running rbenv through dtruss? sudo dtruss -f sudo -u caleb rbenv which ruby

from rbenv.

@sstephenson: ah, yep, that's it. I moved a bunch of stuff from .bashrc to .bash_profile and now ruby -v runs in less than 10ms.

Thanks!

from rbenv.

Fantastic.

from rbenv.

Sorry to re-activate an old thread/issue, but .bashrc / .bash_profile shouldn't make a difference. They are not used for a non-interactive shell, as can be seen from strace -f bash -c exit.

It's more like that bash gets invoked a lot during the rbenv process, where it would be probably faster to source the different parts instead.

from rbenv.

I've started some proof-of-concept, where $(source "$(command -v libexec-script)" args) is used instead of $(libexec-script args), in the pyenv sibling: pyenv/pyenv#356

I think this is interesting for rbenv, too?
What do you think?

from rbenv.