terraform executions delayed by ~ 1 second

[radeksimko]

Whenever I execute any terraform command (even a simple terraform version) there is a noticeable ~1 second delay.

0.12.28 installed via tfenv

executed via tfenv

tfenv 2.0.0 installed from Homebrew via brew install tfenv
terraform installed via tfenv install 0.12.28 && tfenv use 0.12.28

time sh -c 'terraform version'
Terraform v0.12.28
sh -c 'terraform version'  0.29s user 0.59s system 78% cpu 1.111 total

executed directly

time sh -c '/usr/local/Cellar/tfenv/2.0.0/versions/0.12.28/terraform version'
Terraform v0.12.28
sh -c '/usr/local/Cellar/tfenv/2.0.0/versions/0.12.28/terraform version'  0.02s user 0.03s system 101% cpu 0.056 total

0.12.28 installed directly

Installed from Homebrew via brew install terraform

time sh -c 'terraform version'
Terraform v0.12.28
sh -c 'terraform version'  0.03s user 0.03s system 105% cpu 0.059 total

Besides negatively impacting the UX overall, it more specifically impacts users of the Terraform language server, because some editors (e.g. Sublime Text) expect the server to respond within 1 second and they drop the response otherwise, hence breaking e.g. auto-formatting capability.

Environment

macOS Catalina (10.15.5)
Processor: 3.5 GHz Dual-Core Intel Core i7
Memory: 16 GB 2133 MHz LPDDR3

[paultyng]

I think this has to do with the logging calls and the subshells, would be nice to add an option to short circuit even before all the local assignments in the log method if tfenv happens to be used in time sensitive executions (in this case the language server).

[Zordrak]

It's a very unfortunately good point. In all the hard work to improve the visibility and logging, the performance has been overlooked, mostly as it's not been considered a critical issue, however the language server is indeed pushing this issue.

I will take a look at the code shortly and see what we can do to at least shortcut the performance drains when desirable.

We are frankly at the point where bash is the wrong language for this solution, and a Go implementation would make much more sense. I'm kinda hoping Hashicorp want to step up to the plate on that one as I have no Go development experience and a proper versioning mechanism managed in-house would be a much more joined up experience.

[Zordrak]

Ok, this is what I'm thinking:

if [ -n "${BASHLOG_DISABLE:-""}" ]; then
  function log () {
    case "${1}" in
      'error')
        echo "[${1}] ${@:2}" 2>&1;
        exit 1;
        ;;
      'info')
        echo "[${1}] ${@:2}";
        ;;
    esac;
  };
  export -f log;
else
  source "${TFENV_ROOT}/lib/bashlog.sh";
fi;

[Zordrak]

$ time BASHLOG_DISABLE=1 terraform version
Terraform v0.12.29

real    0m0.515s
user    0m0.400s
sys     0m0.135s

$ time terraform version
Terraform v0.12.29

real    0m5.284s
user    0m3.962s
sys     0m1.305s

(My VM has very poor I/O performance :D )

[paultyng]

This may be useful for you, we have a forthcoming tiny binary called tfinstall that you can supply a version to and it downloads the binary, does the sum/sig verification, etc: hashicorp/terraform-exec#29

We could probably augment that to also be able to install from a .terraform-version file or something, or at least be integrated in to the existing scripts. Not a full Go solution, but a partial one at least. We are not looking to replicate the full tfenv user experience, but it could at least assist with some of the parts implemented in bash.

[jvirtanen]

Have you thought about refactoring tfenv to operate the same way as more modern version managers, such as chruby and chnode? Instead of having a shim executable (the terraform script in tfenv), tfenv would only update $PATH and a terraform invocation would directly invoke the real Terraform executable.

(Now that I checked, there is actually a Terraform version manager, aptly called chtf, that already does this.)

[radeksimko]

@Zordrak I think the workaround with BASHLOG_DISABLE you proposed above is sensible and would at least provide relief to the language server users as we could just pass that variable to all executions. 👍

However I still believe that executions should just be quick by default for all users.

[ElvenSpellmaker]

For me on Windows 10 in Cygwin (bash) this has been driving me nuts... tfenv delays it to about 15-20 seconds per run of terraform. It's a nightmare.

time terraform
real 0m19.000s
user 0m1.816s
sys 0m8.072s

time /c/Users/JackBlower/.tfenv/versions/0.13.4/terraform.exe
real 0m0.376s
user 0m0.000s
sys 0m0.031s

BASHLOG_DISABLE does nothing for me.

[Gowiem]

@Zordrak any additional progress on this front? I use tfenv extensively and I'm just realizing now that tfenv is the reason my bash prompt (which utilizes terraform -version) is slow and that hurts.

If not direct progress is being made on this front... Do you know if there is any fast way to collect the current Terraform version from tfenv without the lag being discussed here?

[Gowiem]

@Zordrak friendly ping on this one.

[reegnz]

Oh wow, all this time I was thinking terraform slowed down over the years. Turns out tfenv is the culprit. This is a pretty serious issue for me.
I have a terraform monorepo with hundreds of modules and I want to run terraform fmt in CI to check if everything is properly formatted. This causes a serious bottleneck for that use-case.
Also makes my pre-commit hooks terribly sloooow.

I've made my own basic version manager a few months ago as an experiment and now having tried that one, it doesn't seem to suffer from this issue: https://gist.github.com/reegnz/e11a5c9b4bce0cb02e287e2327799466

So I'll probably integrate that into my CI instead of tfenv, but I'd be glad if tfenv would also fix this, I'd rather use a version manager with a community behind it.

[reegnz]

@Zordrak I prepared two PR-s to fix this annoying issue.

#312 implements loading bashlog.sh conditionally. I regard this one as the inferior solution as it breaks backward compatibility with logging to file, syslog and json.

#313 is fixing bashlog.sh itself, resulting in almost the exact same performance characteristics, without breaking backward compatibility.

Only one of the above two needs merging, I'd rather have #313 be that change.

Everyone in this thread is welcome to test-drive #313 so we can merge it ASAP. The more people verify it, the bigger the confidence in the change not breaking anything.

[ElvenSpellmaker]

I tried replacing my bashlog.sh with the contents from #313 and it's a lot faster now.

Widnows 10 + Cygwin

$ time terraform init
Initializing modules...

Initializing the backend...

Initializing provider plugins...
- Reusing previous version of akamai/akamai from the dependency lock file
- Reusing previous version of hashicorp/aws from the dependency lock file
- Reusing previous version of hashicorp/null from the dependency lock file
- Reusing previous version of hashicorp/tls from the dependency lock file
- Using previously-installed akamai/akamai v1.7.0
- Using previously-installed hashicorp/aws v3.51.0
- Using previously-installed hashicorp/null v2.1.2
- Using previously-installed hashicorp/tls v2.2.0

Terraform has been successfully initialized!

You may now begin working with Terraform. Try running "terraform plan" to see
any changes that are required for your infrastructure. All Terraform commands
should now work.

If you ever set or change modules or backend configuration for Terraform,
rerun this command to reinitialize your working directory. If you forget, other
commands will detect it and remind you to do so if necessary.

real    0m4.408s
user    0m0.182s
sys     0m0.817s

[reegnz]

I have created a dead-simple terraform installer and wrapper in case someone is really blocked by the overhead and needs a dead-simple out-of-your-way wrapper to use multiple terraform-versions.
https://github.com/reegnz/terraform-install

It's less featureful, doesn't try to infer the version from any .tf file, but also tries very hard to be as least intrusive as possible.

I have measured the overhead of the wrapper to be close to non-existant:

Terraform v1.1.5
on darwin_amd64
terraform version  0.04s user 0.03s system 108% cpu 0.058 total

vs without the wrapper I'm seeing around 0.045, so the overhead is around 10ms it seems.

PR-s are welcome.

[reegnz]

I have a very strong feeling now, that bashlog should be completely eliminated from the terraform shim, it's unnecessary overhead.

I did some measurements comparing tfenv to my terraform-install script and the startup overhead tfenv is putting on terraform commands is incredibly high:

❯ hyperfine '~/github/reegnz/terraform-install/terraform version' '~/.cache/terraform/versions/1.1.5/terraform version' '~/github/reegnz/tfenv/bin/terraform version'
Benchmark 1: ~/github/reegnz/terraform-install/terraform version
  Time (mean ± σ):      43.0 ms ±   1.3 ms    [User: 32.0 ms, System: 14.7 ms]
  Range (min … max):    36.8 ms …  46.4 ms    60 runs

Benchmark 2: ~/.cache/terraform/versions/1.1.5/terraform version
  Time (mean ± σ):      32.1 ms ±   0.9 ms    [User: 29.3 ms, System: 10.8 ms]
  Range (min … max):    30.5 ms …  34.9 ms    77 runs

Benchmark 3: ~/github/reegnz/tfenv/bin/terraform version
  Time (mean ± σ):      1.490 s ±  0.009 s    [User: 0.441 s, System: 0.472 s]
  Range (min … max):    1.477 s …  1.508 s    10 runs

Summary
  '~/.cache/terraform/versions/1.1.5/terraform version' ran
    1.34 ± 0.06 times faster than '~/github/reegnz/terraform-install/terraform version'
   46.40 ± 1.38 times faster than '~/github/reegnz/tfenv/bin/terraform version'

Even with the perf improvements to bashlog in #313 it's still significantly slower:

❯ hyperfine '~/github/reegnz/terraform-install/terraform version' '~/.cache/terraform/versions/1.1.5/terraform version' '~/github/reegnz/tfenv/bin/terraform version'
Benchmark 1: ~/github/reegnz/terraform-install/terraform version
  Time (mean ± σ):      43.6 ms ±   1.0 ms    [User: 32.9 ms, System: 15.0 ms]
  Range (min … max):    41.7 ms …  46.7 ms    58 runs

Benchmark 2: ~/.cache/terraform/versions/1.1.5/terraform version
  Time (mean ± σ):      31.9 ms ±   0.8 ms    [User: 29.5 ms, System: 10.7 ms]
  Range (min … max):    30.1 ms …  33.7 ms    75 runs

Benchmark 3: ~/github/reegnz/tfenv/bin/terraform version
  Time (mean ± σ):     132.3 ms ±   3.1 ms    [User: 69.4 ms, System: 37.3 ms]
  Range (min … max):   126.8 ms … 138.1 ms    21 runs

Summary
  '~/.cache/terraform/versions/1.1.5/terraform version' ran
    1.36 ± 0.05 times faster than '~/github/reegnz/terraform-install/terraform version'
    4.15 ± 0.14 times faster than '~/github/reegnz/tfenv/bin/terraform version'

Keep in mind that terraform-install is fully bash3 compatible, no dependencies wrapper (only bash required). Surely tfenv can utilize the lessons learned there, and remove unnecessary things from what's supposed to be a simple shim.

[cspotcode]

Am I correct that tfenv internally uses a bunch of subprocesses, since it calls out to its own libexec scripts a lot? And each of those needs to repeat bootstrapping tasks? Seems like refactoring into functions that can each be lazy-loaded into a single bash process might help, on top of removing bashlog as @reegnz has suggested.

[reegnz]

@cspotcode yes, you're correct in that assumption, currently it forks subprocesses on each logger call, which results in a huge overhead. I think that's not a problem during tfenv calls (eg. install, list, etc), but the terraform shim should probably eliminate the entirety of bashlog calls and do the bare minimum it needs to do (select the appropriate binary version, and reexec with that binary).

[RoryKiefer]

Music to my ears @reegnz. Thanks for your PR (https://github.com/tfutils/tfenv/pull/313/files to anyone interested) and I hope it gets merged soon because my organization is absolutely getting killed by the performance of tfenv. Using IntelliJ file watchers with a tfenv-terraform-wrapper backed script is a lesson in brutal pain, and its adding significant time to our CD pipeline, too.

[cspotcode]

Note that anyone can start using these improvements today. Use the Manual installation instructions and checkout the appropriate branch.

[reegnz]

I also have a homebrew-installable alternative for those who don't shy away from new things: https://github.com/reegnz/terraform-install
We'll see how this change goes, I have high hopes for fixing the perf issues of tfenv. Until then I've moved to my own terraform wrapper solution, because the perf issues are unbearable.

[reegnz]

FYI fix is now released as part of https://github.com/tfutils/tfenv/releases/tag/v3.0.0

[cspotcode]

True, the logger calls fork a lot. But I was also thinking about how it forks the various binaries declared in ./libexec

…

On Tue, Mar 8, 2022, 6:03 AM Zoltán Reegn ***@***.***> wrote: @cspotcode <https://github.com/cspotcode> yes, you're correct in that assumption, currently it forks subprocesses on each logger call, which results in a huge overhead. I think that's not a problem during tfenv calls, but the terraform shim should probably eliminate the entirety of bashlog calls and do the bare minimum it needs to do (select the appropriate binary version, and reexec with that binary). — Reply to this email directly, view it on GitHub <#196 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAC35OGNEVYMSFKIRQLMHXLU64XWJANCNFSM4OVSFJ5Q> . You are receiving this because you were mentioned.Message ID: ***@***.***>