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?

[radiosilence]

@danhper any news on keeping asdf-exec up to date? It seems fantastically fast!!

[vsviridov]

asdf version v0.8.0-c6145d0

vsviridov in ubuntu-scb in scb-domain-ts on  master [!] is 📦 v0.0.1 via 
❯ time ~/.asdf/shims/node -v
v15.14.0

real    0m0.690s
user    0m0.347s
sys     0m0.627s

vsviridov in ubuntu-scb in scb-domain-ts on  master [!] is 📦 v0.0.1 via 
❯ time ~/.asdf/installs/nodejs/15.14.0/bin/node -v
v15.14.0

real    0m0.047s
user    0m0.021s
sys     0m0.029s

Over half a second is too much. Node version is part of my prompt (via starship.rs) and it's extremely slow.

[TeddyDD]

Seems like this tool is trying to sovle the issue.

[eproxus]

Just hit this problem today trying to make a prompt that shows the current version of various tools. It's not only that asdf current or asdf current <plugin> is slow, it's that every shim call is slow. That means you can't even run e.g. ruby -v because it is wrapped in the same slow logic as asdf current. Furthermore, this means that any shell script or loop that runs e.g. ruby many times is adding (on my machine) 0.25 s for every call to ruby.

In my opinion, this is a major drawback against using asdf despite all the niceties it brings. If the README would state that it adds 0.25 seconds to every execution of anything installed with asdf I doubt few people would use it.

There seems to have been some research earlier in this issue that hinted at possible improvements. Is there anything we can do to fix this problem in asdf itself?

[eproxus]

@danhper

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!

Correct me if I'm wrong, but the setting legacy_version_file defaults to no so we should be able to speed up the logic for the default case quite a bit?

For reference, this Fish shell function currently implements asdf current <plugin> and runs in ~1 ms on my machine:

function asdf_current --argument-names lang
    set current (pwd)
    set versions
    set root (dirname $HOME)

    env_lang_version=ASDF_(string upper $lang)_VERSION set env_version $$env_lang_version

    if test -n "$env_version"
        echo $env_version
        return 0
    end

    while test "$current" != "$root"
        if test -e $current/.tool-versions
            set -a versions (string split "\n" < $current/.tool-versions)
        end
        set current (string join "/" (string split "/" $current)[..-2])
    end

    for ver in $versions
        if string match --quiet "$lang *" $ver
            echo (string split -f2 " " "$ver")
            return 0
        end
    end
end

This obviously isn't usable in asdf, but shows that there's room for improvement.

[RafalSkolasinski]

Hi, would it be a good idea to add somewhere visible warning about it or in FAQ?

I just had been writing some helper scripts for i3 and had in my config things along

bindsym <keybinding here> exec ~/.asdf/shims/<command here>

and took me quite some time to figure what adds the extra latency. For illustration purpose, a trivial python script

$ cat test.py
import i3ipc

if __name__ == "__main__":
    i3 = i3ipc.Connection(auto_reconnect=True)
    workspaces = i3.get_workspaces()
    for ws in workspaces:
        print(ws.name)

can take >300ms

$ which python3
/home/rskolasinski/.asdf/shims/python3

$ time python3 test.py
1:<span font_desc='JetBrains Mono Medium 13'> 1 </span>
2:<span font_desc='JetBrains Mono Medium 13'> 2 </span>
4:<span font_desc='JetBrains Mono Medium 13'> 4 </span>
17:<span font_desc='JetBrains Mono Medium 13'> 17 </span>
3:<span font_desc='JetBrains Mono Medium 13'> 3 </span>
5:<span font_desc='JetBrains Mono Medium 13'> 5 </span>
10:<span font_desc='JetBrains Mono Medium 13'> 10 </span>
noname

________________________________________________________
Executed in  366.75 millis    fish           external
   usr time  299.16 millis  531.00 micros  298.63 millis
   sys time  197.50 millis  218.00 micros  197.28 millis

While when using system python

$ time /usr/bin/python3 test.py
1:<span font_desc='JetBrains Mono Medium 13'> 1 </span>
2:<span font_desc='JetBrains Mono Medium 13'> 2 </span>
4:<span font_desc='JetBrains Mono Medium 13'> 4 </span>
17:<span font_desc='JetBrains Mono Medium 13'> 17 </span>
3:<span font_desc='JetBrains Mono Medium 13'> 3 </span>
5:<span font_desc='JetBrains Mono Medium 13'> 5 </span>
10:<span font_desc='JetBrains Mono Medium 13'> 10 </span>
noname

________________________________________________________
Executed in   78.47 millis    fish           external
   usr time   70.58 millis  602.00 micros   69.98 millis
   sys time    8.00 millis  228.00 micros    7.78 millis

P.S. This in no means take away from how awesome tool asdf-vm is, it'd be just good to know limits when using it for latency-critical scripts.

[RafalSkolasinski]

Sorry to nag, but is there anything planned to improve out-of-the-box experience with asdf-vm on this front?

In my use-case I only care about being able to set one global version of a tool (python, go, whatever I manage with asdf) and would be really nice if asdf-vm could achieve this without introducing a massive latency....