rbenv-gemset hooks adding ~700ms to every `ruby` execution

[nrser]

Using rbenv-gem version 0.5.9 on macOS 10.12.6 and started to notice running ruby was much slower:

$ time ruby -e "puts 'yo'"
yo

real	0m0.821s
user	0m0.419s
sys	0m0.207s

Ran with RBENV_DEBUG=1 and noticed calls in the gemset.bash scripts. I went into etc/rbenv.d/*/gemset.bash and commented out all three files:

$ time ruby -e "puts 'yo'"
yo

real	0m0.108s
user	0m0.066s
sys	0m0.015s

Which isn't great, but I can live with 100ms. The 800ms start time with the rbenv-gemset hooks enabled is quite noticeable to me though. Is this a standard amount of delay? If not, about how much time should I expect the plugin to add?

I'm running Ruby 2.5.0, but similar results across the board. I have no active gemset, I'm not in a directory that has a gemset, and I have no gemsets for Ruby 2.5.0... so it doesn't seem like the hooks should really have to do anything as soon as they can figure that stuff out?

I toyed around with the hook code a bit; it doesn't seems like there's any one super-slow operation, just a bunch of small ones adding up. Maybe I have something in my setup that is considerably slowing down shell spawning, causing me to feel a lot more pain from the hook code.

Anyways, the hook code is short and clean, and don't totally understand it yet but it seems like it could be optimized considerably... I don't see any short-circuiting. It seems like it should be able to quickly figure out if it doesn't need to do anything and bail out.

Also, it looks like there are places where work is duplicated across the various scripts in the hooks execution path, like the sub-shell to rbenv-gemset file here:

https://github.com/jf/rbenv-gemset/blob/master/etc/rbenv.d/which/gemset.bash#L7

then four lines later sub-shelling rbenv-gemset active

https://github.com/jf/rbenv-gemset/blob/master/etc/rbenv.d/which/gemset.bash#L11

which looks like one of the first things it does is sub-shell rbenv-gem-set-file:

https://github.com/jf/rbenv-gemset/blob/master/etc/rbenv.d/which/gemset.bash#L11

Seems like that stuff could be cached in variables or passed as extra arguments to avoid the duplicate effort.

Sub-shells aren't super cheap... it's a full process spawn. /bin/bash -c exit is around 5-6ms on my system, which really adds up.

Additionally, is there a reason those shells in which/gemset.bash (which is the slowest hook on my system btw) are spawning rbenv-gemset instead of going directly to the libexec/rbenv-gemset-*? It seems like they probably have enough info available to just directly invoke the end-executables and skip going through the user interface entry point and all the commands (many of which are again sub-shells).

I forked the repo and am going to hack in and see if I can get the latency down at least in the case where there's no need to load a gemset, because I've now used the plugin to isolate some gems I use as system utils and it's been really useful and wonderful for that (thanks!). Let me know if you're interested in checking out my changes.

[nrser]

I did some pretty radical reorganization and optimization of the which and exec hooks that dropped the time added from the ~700ms I was seeing yesterday to ~40ms (on the same simple ruby -e test).

There's probably bugs and breakage, but it works when RBENV_GEMSETS is provided in the environment, which is what I need it for right now.

You can check it out if you're interested at:

https://github.com/nrser/rbenv-gemset

A brief summary of the approach:

1. Introduce a lib/rbenv-gemset.bash library that is sourced in to the hooks.

2. Migrate over the libexec/rbenv-gemset-* functionality that was getting sub-shelled out in the hooks to library functions that run in-process and set their results as variables.

   Bash can't return anything but status codes from functions, so unless you want to pay for sub-shell forks you have to set variables in the functions that are then read by the caller after the call (like C reference variables, which, incidentally, is the way to really make C fly according to the ultra-performance memory grid people I know).

   There are contortions (involving eval from my understanding) that you can do to pass in the name of the variable you want the function to set, but, since the scope is so limited here, they all just set well-known variable names.

3. Since there doesn't seem to by much of anything dynamic going on the hooks (exec and which ones at least - their output seems like a pure function of their environment) I set up a rbenv_gemset_ensure VAR_NAME function that checks of the variable is set, and if it's not calls _rbenv_gemset_set_VAR_NAME to set it.

   This means that setting the variables (which inevitably involves sub-shelling) happens on-demand and only once per process.

4. Bail out of the hooks early if there are no active gemsets. This honestly probably made most the difference ;)

If people are interested about this stuff we can look at how to integrate it. It totally solves my immediate issue, which is what I needed, but if other people aren't seeing that kind of latency or it doesn't bother them than I guess I doubt you would want to complicate the code so much.

Oh, the one (intentional) possible breaking change: I removed the dynamic finding of the gem executable that was done via

$("$(rbenv which gem)" env gemdir)

for use in the exec hook to just use

$("${rbenv_gemset_prefix}/bin/gem" env gemdir)

(where $rbenv_gemset_prefix=$(rbenv-prefix) through the caching system)

I figured most people have gem at $(rbenv-prefix)/bin/gem, and the previous approach seemed like a crazy performance hit for what I have to guess is the common case: the rbenv which goes all the way through the hooks again in a sub-shell.

There could of course be a flag or setting for people who need dynamic resolution of gem so only the people that needed it had to pay for it.

Also, I now realize all these changes could be behind some RBENV_GEMSET_BE_FAST flag. That's probably how I should have done it in the first place, but I didn't think of it 'till now. Oh well.

[jf]

Excellent! As a note, I am rather pre-occupied for at least the next 2 weeks. But I will take a look at this. Thanks!

[nrser]

Cool. Yeah, give it a check if/when you get some time. It's a bit of a rough cut, but you can get the idea, and the performance boost is quite significant.

[cabello]

Yeah, I was just able to verify this issue in my case it was 1.7s +- 150ms and after uninstalling rbenv gemset I got it down back to 70ms +- 5ms.

[AprilArcus]

Friendly poke to @nrser and @jf to please merge this fork and publish an update to homebrew!

[jf]

My apologies, folks! It seems I've been really late on this one :(

I will take some time before the end of the year to look at this. Thank you for your patience!

[AprilArcus]

I've found an error in @nrser's fork that causes iteration over gemsets to include space literals. I've fixed this, and submitted a PR here.

[AprilArcus]

@jf friendly new years poke!

[jf]

@AprilArcus gotcha and thank you for that. I've been meaning to get to it... but things kept getting in the way... I should get some time this weekend to look into this.

[jf]

I've found an error in @nrser's fork that causes iteration over gemsets to include space literals. I've fixed this, and submitted a PR here.

Thanks for this, and the fix is correct. We use spaces as the delimiter in .rbenv-gemsets so gemset names should not have spaces.

[nrser]

I've found an error in @nrser's fork that causes iteration over gemsets to include space literals. I've fixed this, and submitted a PR here.

Awesome @AprilArcus. Yeah, I never use more than one gemset so I didn't catch that.

[dmitrym0]

Sad-face:

[WARN] - (starship::utils): Executing command "/Users/dmitrymarkushevich/.rbenv/shims/ruby" timed out.
[WARN] - (starship::utils): You can set command_timeout in your config to a higher value to allow longer-running commands to keep executing.