Improve bashlog.sh performance

[reegnz]

Performance is improved by an order of magnitude by ensuring that logging does not fork unnecessarily:

• forking to date only happens if timestamps are actually used
• forking to basename is replaced with bash expansion
• forking to dirname is replaced with bash expansion

Fixes #196

[reegnz]

Benchmarks

Before

❯ time ./terraform -version
Terraform v1.1.0
on darwin_amd64
./terraform -version  0.44s user 0.48s system 62% cpu 1.489 total

After

❯ time ./terraform -version
Terraform v1.1.0
on darwin_amd64
./terraform -version  0.07s user 0.04s system 78% cpu 0.147 total

I made sure that the log function stays backward compatible, so there shouldn't be any breaking changes.

[reegnz]

@Zordrak could you please have a look?

[cspotcode]

I just tested this. Here are some hyperfine results:

ubuntu:~/.tfenv$ hyperfine './versions/1.1.7/terraform version'
Benchmark 1: ./versions/1.1.7/terraform version
  Time (mean ± σ):      37.7 ms ±   9.4 ms    [User: 34.4 ms, System: 14.9 ms]
  Range (min … max):    27.2 ms …  69.6 ms    42 runs

ubuntu:~/.tfenv$ hyperfine './bin/terraform version'
Benchmark 1: ./bin/terraform version
  Time (mean ± σ):      85.3 ms ±  14.6 ms    [User: 69.1 ms, System: 27.3 ms]
  Range (min … max):    66.6 ms … 120.9 ms    30 runs

Only ~45ms of overhead is pretty good. I hope this gets merged!

[cspotcode]

Here is what I propose changing to maximize performance of the terraform shim, including @reegnz's idea for bashlog

• conditionally enable bashlog.sh
  • @reegnz What environment variables do we check for this?
  • If bashlog is disabled, then declare log function as a shim.
• Avoid all spawning of libexec executables by refactoring them into bash functions
  • The only ones used by the terraform shim are: (this list ignores commands that install new versions, which are expected to be slow)
  • tfenv itself
  • tfenv-exec
  • tfenv-version-name
  • tfenv-version-file
  • This refactor will not remove the ability to exec them
  • It will refactor their implementations into functions in lib
  • The libexec scripts will delegate to these functions.
  • The terraform shim will source and call these functions directly

[reegnz]

@cspotcode I think we could use something like z BASHLOG_ENABLE=1 otherwise it should be a noop. We probably should default to no-log IF terraform is already installed and all that the wrapper is doing is selecting the installed version and exec-ing to it. The terraform wrapper should default to disabled (so noop), unless the automatic installation happens, then we'd most definitely want to see what's going on.

[cspotcode]

How about TFENV_BASHLOG_ENABLE to namespace it the same way as the other environment variables?

We can declare a function enable_full_bashlog that can be called in the auto-install codepaths to switch to the full bashlog immediately before doing stuff that needs to be logged.

[cspotcode]

Tests are passing locally but we need a maintainer to trigger the CI workflow.

[cspotcode]

I realized I did not explain my implementation.

I noticed that log debug ... is a no-op unless you have debugging enabled via log level. In the common case where you already have terraform installed, the only log messages in the terraform shim are debug logs.

So I changed helpers.sh to declare a function log shim that will lazy-load the full bashlog as soon as non-debug logging happens. If you have debug logging enabled, it does the right thing and loads bashlog immediately.

This avoids the need for any new environment variables, so it's not a behavioral change. Things should log in the same way they always have.

I also moved some of the libexec commands into lib as functions, which avoids a few spawns.

[reegnz]

@cspotcode that is awesome! I did some additional perf tweaking (getting rid of forking to basename and dirname in the hot path), it added another significant bump in perf:

Before tweaking:

❯ hyperfine -w 10 '~/.cache/terraform/versions/1.1.5/terraform version' './terraform version'
Benchmark 1: ~/.cache/terraform/versions/1.1.5/terraform version
  Time (mean ± σ):      36.3 ms ±   0.9 ms    [User: 31.7 ms, System: 13.5 ms]
  Range (min … max):    34.5 ms …  38.7 ms    67 runs

Benchmark 2: ./terraform version
  Time (mean ± σ):     105.8 ms ±   2.3 ms    [User: 50.8 ms, System: 36.8 ms]
  Range (min … max):   101.8 ms … 111.1 ms    25 runs

Summary
  '~/.cache/terraform/versions/1.1.5/terraform version' ran
    2.91 ± 0.10 times faster than './terraform version'

After the tweaks:

❯ hyperfine -w 10 '~/.cache/terraform/versions/1.1.5/terraform version' './terraform version'
Benchmark 1: ~/.cache/terraform/versions/1.1.5/terraform version
  Time (mean ± σ):      36.1 ms ±   1.0 ms    [User: 31.8 ms, System: 13.4 ms]
  Range (min … max):    34.0 ms …  39.8 ms    68 runs

Benchmark 2: ./terraform version
  Time (mean ± σ):      73.8 ms ±   1.5 ms    [User: 44.1 ms, System: 25.8 ms]
  Range (min … max):    70.9 ms …  77.6 ms    36 runs

Summary
  '~/.cache/terraform/versions/1.1.5/terraform version' ran
    2.05 ± 0.07 times faster than './terraform version'

This PR starts to look really good now!

[reegnz]

@pinkplus please have another look, I think everyone's requirements are met now with the latest code changes.

[pinkplus]

The idea of lazy loading log() is really clever. I've confirmed that it works with Bash 3 as well and is super fast. Thanks!

[cspotcode]

Excellent, thanks for confirming!

Is there anything else Zordrak needs to merge this? Looks like automated tests run on both Mac and Linux, so I think we've covered all our bases.

[RoryKiefer]

Many thanks for tackling these issues, cspot/reegnz! ❤️ This is a fantastic performance improvement.

[cspotcode]

@Zordrak anything else you need from us before this is merged?

[RoryKiefer]

Is there anything anyone from the community can do to bolster this effort? (I may volunteer as tribute...)

[RoryKiefer]

I went ahead and switched my tools test branch over to the fork, and have noticed the speed increase (and no ill effects after a week). If I encounter errors, I'll PR a fix to the fork. When TFEnv is in the critical path of an IntelliJ/JetBrains "File Watcher", it no longer keeps 10 instances of TFEnv running in parallel for several minutes while the machine fans go crazy. (MBP, Intel). In fact, no fan spinup at all. The difference is night and day and feels exactly like what my terraform wrapper felt like in this scenario before I added TFEnv to it.

Edit: I should add that my fans no longer even spin back up at all, even when Im plugged in to the left side of my machine, which is saying something. Before this branch, having IntelliJ open w/ a "file watcher" that ran TFEnv meant the fans were spinning frequently. Basically any time I ran a git operation on my terraform environment to elicit a fmt of the changed files.

[cspotcode]

I think we need to wait for @Zordrak to merge. I wonder if there is something about this change that makes them hesitant to merge? Perhaps something that feels risky to them that we might be able to better explain to smooth out the code review process?

[cspotcode]

Bump! Can we at least get this issue or pull request pinned? That way, anyone who hits similar performance issues will be able to find this branch and use it.

[cspotcode]

Bump! Yet again... I am onboarding other members of my team onto some terraform projects. I would really like to get this merged. @Zordrak is there anything we can do to get this merged?

[Zordrak]

Looking at this now. Apologies for the long delay and thank you very much for the massive effort here.

[joelsdc]

@Zordrak do you think you can make a release? This improvement is a BIG one.

[cspotcode]

In the interim, the git installation method works well.