asdf shims adding too much time to use them in a shell prompt

[stevenocchipinti]

Hello,

Not sure if this is the right place to report this issue but I've noticed using asdf is quite slow for executing commands.

This is ruby using chruby:

$> time ~/.rubies/ruby-2.5.0/bin/ruby -v
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin16]

real    0m0.019s
user    0m0.009s
sys 0m0.006s

and node using nvm:

$> time ~/.nvm/versions/node/v9.1.0/bin/node -v
v9.1.0

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

Steps to reproduce

This is ruby using asdf:

$> time /usr/local/opt/asdf/shims/ruby -v
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin16]

real    0m0.305s
user    0m0.130s
sys 0m0.126s

and node using asdf:

$> time /usr/local/opt/asdf/shims/node -v
v8.9.4

real    0m0.272s
user    0m0.119s
sys 0m0.109s

When having a shell prompt that prints the version number of ruby and node, this adds half a second to each command!

I love the idea of asdf but I don't want to give up version numbers in my prompt so I won't be using asdf in its current state unless I can find a workaround.

Any ideas or advice would be welcome - thanks

Environment

OS: OSX

asdf version: v0.4.2

[Stratus3D]

You are right, we need to investigate this. asdf current take almost a second to run on my machine:

asdf current  0.39s user 0.50s system 100% cpu 0.893 total

Now I have over half a dozen plugins installed, but even running it for just one version number still causes it to take a quarter of a second.

[Stratus3D]

Reminder for myself: http://tldp.org/LDP/abs/html/optimizations.html

[ppdeassis]

Same here (macOS 10.12.6, Terminal 2.7.4 and bash GNU bash, version 3.2.57(1)-release (x86_64-apple-darwin16)). Showing ruby, node and python versions is adding over a second with asdf version v0.5.0.

Ruby

→ time ~/.asdf/shims/ruby -v
ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]

real    0m0.333s
user    0m0.200s
sys 0m0.081s

# --

→ time asdf current ruby
2.5.1   (set by $HOME/.tool-versions)

real    0m0.433s
user    0m0.269s
sys 0m0.130s

Node

→ time ~/.asdf/shims/node -v
v10.7.0

real    0m0.219s
user    0m0.132s
sys 0m0.065s

# --

→ time asdf current nodejs
10.7.0  (set by $HOME/.tool-versions)

real    0m0.501s
user    0m0.308s
sys 0m0.155s

Python

→ time ~/.asdf/shims/python --version
Python 3.7.0

real    0m0.197s
user    0m0.121s
sys 0m0.062s

# --

→ time asdf current python
3.7.0   (set by $HOME/.tool-versions)

real    0m0.476s
user    0m0.302s
sys 0m0.142s

_edit_: included macOS version and _timings_ with asdf current too

[Stratus3D]

@ppdeassis so asdf current doesn't actually execute the version commands directly (e.g. python --version) so in theory it could be faster than the actual version command that tool offers. asdf current should really only have to read a few files and print the version it has read from the file. So ideally it would be fast enough to use in the shell prompt.

[ppdeassis]

Yeah, probably. But even then - achieving the direct shim execution _timings_ - I think there may be something else.
The timing differences presented by @stevenocchipinti are big:

Checkout ruby, for example:

This is ruby using chruby:
$> time ~/.rubies/ruby-2.5.0/bin/ruby -v
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin16]

real 0m0.019s
user 0m0.009s
sys 0m0.006s

This is ruby using asdf:

$> time /usr/local/opt/asdf/shims/ruby -v
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin16]

real 0m0.305s
user 0m0.130s
sys 0m0.126s

That's 0.019s (chruby) vs 0.305s (asdf) => ~16x slower. And there's also the overhead of asdf current (vs the direct shim execution) as pointed out.

But again, as @stevenocchipinti pointed out, I don't know if it's an asdf specific issue or it may have something to do with the way _plugins_ (e.g. asdf-ruby) are built.

[Stratus3D]

@ppdeassis the only thing involved is the plugin's exec-env callback script if it is present. Most plugins do not include an exec-env script as it's not needed. The ones that do (like asdf-ruby) do relatively simple things like set environment variables. There isn't really anything we can do to optimize that logic, and it's unlikely to be slow (benchmarking of just the exec-env scripts could confirm this).

[Stratus3D]

I believe it's due to the logic in asdf's version lookup code. It looks for one or more files in the current directory, and climbs up to the parent directory if nothing is found. This continues until a version is found or the top level directory is reached. asdf current is faster for me in a directory containing a .tool-versions file than it is in deeply nested directory many layers below the .tool-versions file.

[brlodi]

Correct me if I'm wrong, but the lookup appears to traverse the directory hierarchy per plugin, so the overhead scales with the number of enabled plugins. Since those are making file read calls they're relatively expensive. It could be a significant improvement to traverse the directory tree once, compiling applicable versions from .tool-versions files, and then output based on that.

[Stratus3D]

@brlodi yes, that is exactly why the asdf current command is so slow. If it has to traverse 5 directories to find the right version and you've got 5 plugins, it's going to do at least 25 reads (more if legacy version file support is turned on). The reason it does things per plugin is because our version lookup functions can only lookup one version at a time. Obviously this isn't ideal, but it would take quite a bit of refactoring to look up all versions in one directory hierarchy traversal. We'd have to keep track of the versions that haven't been found an only stop the traversal when all plugin versions have been found.

[Fire-Dragon-DoL]

Is there an option to disable shims entirely? They don't do anything relevant to me, I really just need updating a bunch of env variables when I "switch env", but they do slow down every command

[vic]

Could you people test with current master (cc7886309271b21a7da3fccf8efc892b546ffbbb) and report if shim execution has improved with the new shim exec?

[stevenocchipinti]

I've just cloned the current master - which is 2e22409:

$> git show
commit 2e22409c90f6cadd57bf1e1a2aa313eabcc9f2ff (HEAD -> master, origin/master, origin/HEAD)
Author: Victor Hugo Borja <[email protected]>
Commit: Victor Hugo Borja <[email protected]>

    v0.6.4-dev

$> asdf -v
version: v0.6.4

...

Still seems to be slow.

Ruby

Installed with asdf:

$> time ~/.asdf/shims/ruby -v
ruby 2.6.0p0 (2018-12-25 revision 66547) [x86_64-darwin16]

real    0m0.280s
user    0m0.195s
sys 0m0.158s

Installed with chruby/ruby-install:

$> time ~/.rubies/ruby-2.5.3/bin/ruby -v
ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-darwin16]

real    0m0.033s
user    0m0.014s
sys 0m0.010s

NodeJS

Installed with asdf:

$> time ~/.asdf/shims/node -v
v10.15.0

real    0m0.284s
user    0m0.197s
sys 0m0.160s

Installed with nvm:

$> time ~/.nvm/versions/node/v10.15.0/bin/node -v
v10.15.0

real    0m0.021s
user    0m0.008s
sys 0m0.006s

[metakirby5]

As a workaround, I was able to incorporate asdf into my prompt with no noticeable performance impact by implementing the lookup myself in bash.

  # Code goes somewhere in your prompt function.

  asdf_path="$PWD"
  asdf_info=

  # Make sure asdf is currently active.
  if [ "$ASDF_BIN" ]; then

    # Traverse up directories until we hit an asdf directory or filesystem root.
    until [ -f "$asdf_path/.tool-versions" -o "$asdf_path" == '' ]; do
      asdf_path="${asdf_path%/*}"
    done
    asdf_path="$asdf_path/.tool-versions"

    # Use array manipulations and IFS to replace newlines with '/'.
    if [ -f "$asdf_path" ]; then
      IFS=$'\n'
      asdf_info=($(<"$asdf_path"))
      IFS='/'
      asdf_info="${asdf_info[*]}"
    fi
  fi

An example of what "$asdf_info" looks like at the end is: ruby 2.6.3/python system

[danhper]

@metakirby5 This is mostly how it was implemented a while ago, but as asdf started handling other things, the logic got more complex, making things slower.
For example, we need to check for "legacy version files", such as .python-version or so if present. We also support setting the version using environment variables.
Making asdf faster is definitely important for this project, so any help to make this happen is more than welcome!

[stevenocchipinti]

Just a random thought, if that legacy logic is where the bottleneck is, would it be worth disabling that behaviour by default and legacy users can enable legacy_mode via an env variable or something?

[danhper]

default and legacy users can enable legacy_mode via an env variable or something

We already have a setting for this in asdf configuration file: https://asdf-vm.com/#/core-configuration?id=homeasdfrc

I am currently doing a small experiment on my side with the lookup logic implemented in Go.
It supports most of the features of asdf, including legacy_mode and is vastly faster than what we have now.
https://github.com/danhper/asdf-exec

[jordan-brough]

@danhper that's fantastic. 👍 Please keep going with that. Speed-ups for me:

Normal asdf

$ time ruby -v
ruby 2.6.2p47 (2019-03-13 revision 67232) [x86_64-darwin17]
real 0m0.262s   user 0m0.137s   sys 0m0.158s

With asdf-exec

$ time ruby -v
ruby 2.6.2p47 (2019-03-13 revision 67232) [x86_64-darwin17]
real 0m0.041s   user 0m0.015s   sys 0m0.014s

Direct path to binary

$ time ~/.asdf/installs/ruby/2.6.2/bin/ruby -v
ruby 2.6.2p47 (2019-03-13 revision 67232) [x86_64-darwin17]
real 0m0.026s   user 0m0.012s   sys 0m0.009s

[ppdeassis]

Sorry for the delay, guys.

My findings won't probably add anything new, but...
I have just upgraded asdf to v0.7.2 and now asdf current _beats_ "direct shim execution" - but still far from "direct binary execution" by ~200ms (asdf lookup time?):

On my previous comment, with asdf v0.5.0, "direct shim execution" was faster than asdf current.

asdf current

$ time asdf current ruby
2.5.1    (set by $HOME/.tool-versions)

real    0m0.237s
user    0m0.132s
sys 0m0.126s

"direct shim execution"

$ time ~/.asdf/shims/ruby -v
ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]

real    0m0.342s
user    0m0.191s
sys 0m0.177s

"direct binary execution"

$ time ~/.asdf/installs/ruby/2.5.1/bin/ruby -v
ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]

real    0m0.021s
user    0m0.011s
sys 0m0.006s

[vic]

So, I just created a new plugin to integrate with direnv which can hopefully improve execution time a lot. It works by exposing your asdf-tools environment (PATH and any other env-var set by your active plugins) and let direnv manage it.

Be sure to checkout the README for https://github.com/asdf-community/asdf-direnv

[vic]

And benchmarks: https://github.com/asdf-community/asdf-direnv#benchmark

[jeff-hykin]

Any update on this? It is still incredibly slow for me to the point that I just disabled asdf.

It seems like the entire parent lookup could be done in one command like this (48ms on a low-end macbook pro)

asdf_path="$PWD"
ls_parents=""
# aggregate ls until we hit root
until [ "$asdf_path" == '' ]; do
    asdf_path="${asdf_path%/*}"
    ls_parents="$(ls -1 "$asdf_path")

:::$asdf_path:::
$ls_parents"
done

echo "$ls_parents"

Then lookups for any plugin (legacy or not) can just check against that string rather than performing 25 separate calls.

I don't have any local versions and I very rarely need to switch versions, but asdf is slowing down my terminal every time I open it.

I'd also be fine if asdf delayed the lookup until a command is used. e.g. don't look for .python-version until the user executes pip or python etc. The number of times I open my terminal vastly outweighs the number of times I call those commands.

[mindreframer]

Any news on this issue? It seems like there could be some solutions, if given enough priority.

[TeddyDD]

I encountered the same issue. With shims:

time lua -e "os.exit()"
________________________________________________________
Executed in  160,92 millis    fish           external
   usr time  171,70 millis  503,00 micros  171,20 millis
   sys time   42,09 millis  144,00 micros   41,95 millis

I replaced .asdf/shims/lua with symlink to executable:

ln -s ../installs/lua/5.4.0/bin/lua lua

time lua -e "os.exit()"
________________________________________________________
Executed in    2,58 millis    fish           external
   usr time    2,64 millis  452,00 micros    2,19 millis
   sys time    0,15 millis  148,00 micros    0,00 millis

Maybe using symlinks instead of wrapper scripts would do the job?