Terraform Language Server is Slow and Laggy

[ekristen]

Not sure what's going on but ever since I upgrade to the latest version, the language server has been extremely lagging and slow.

It's keeping files from being saved during formatting, when it detects errors I can see the red underline disappear character by character after it's been fixed. It's completely unusable.

Unfortunately since you haven't gone back and resigned the older versions after the GPG issue I can't figure out when this started to occur.

[radeksimko]

Hi @ekristen
I am aware of one particular limitation which may be causing some delays: #426

However I can't conclusively say that what you're experiencing is related to that particular issue.

Can you provide me any more details to better understand what the problem may be?

• share a gist with LS log available from the relevant Output pane prefixed with terraform-ls:, anything between Launching language server: and the last line, minus any sensitive data
• how many workspaces/folders do you have open in VS Code at a time?
• how many unique providers do you use in your configuration?
• is there more than 1 LS process running at a time?
• how much resources (memory/CPU) does each process of LS use?

[radeksimko]

I also just found a bug that may be related to what you described

when it detects errors I can see the red underline disappear character by character after it's been fixed

#488

[btmills]

I'm experiencing the same issue described by OP: formatting on save runs slowly if I don't cancel it, and error squigglies disappear at 1-2 characters per second. Here's the debug information:

• Language server log, scrubbed of sensitive data: https://gist.github.com/btmills/3895471b51aad8478156febd929c8cbd
• One workspace is open. It has ~10 top-level folders, but only one has any Terraform files in it. There are 6 .tf files in the repository, all in one top-level folder.
• Two providers:
  1. digitalocean/digitalocean 2.3
  2. hashicorp/aws 3.34
• ps -ax | grep terraform-ls reports only one instance.
• While waiting to save, terraform-ls takes 100-120% CPU and 150-250MB memory.
• Other system info:
  • 2017 15" Macbook Pro
  • macOS 11.3.1
  • VSCode 1.56.0
  • Terraform extension v2.10.2
  • terraform-ls v0.16.2

The delay appears to be proportional to the number of changes I make at about 1s per change. For example, if I type "1" and save, saving takes ~1s. If I type "12345" and save, then backspace all 5 characters and save again, each save takes ~5s. "1234567890", save, backspace all 10 characters, save, and each save takes ~10s. If I select and delete multiple lines in a single change, saving takes 1s, and undoing it and saving takes 1s. If I type a whole comment, saving takes minutes, but if I select and delete it, it's ~1s. You can see this in the timestamps of the Gist I shared, where there's a message server.go:175: Processing 1 requests about once every second while I'm waiting for it to save.

Hopefully this helps. Is there any other information I can provide?

[radeksimko]

@btmills Thank you for providing these details. That's a lot of details and they may as well be symptoms of different unrelated problems, so I'll try to pick and respond to those that may seem more "out of ordinary" than others.

150-250MB memory.

This is within the area of expected memory usage at this point, see #506 for little more context. In general the usage is expected to rise with the number of (unique) providers in use throughout the workspace and size of these providers (e.g. number of resources and data sources, or fields within those).

Currently schemas are preloaded into memory before we even know whether or not we were able to source the schema locally. If you always init locally and schemas are source-able locally then you might benefit from the opt-out. That way we'd only load aws + digitalocean into memory and no other provider schemas in your example.

Feel free to subscribe to that issue to be notified about updates in that area.

While waiting to save, terraform-ls takes 100-120% CPU

Just to double check - are you absolutely sure this amount of CPU is allocated by terraform-ls and not terraform?

The reason I'm asking is because (as evident from the attached log) VS Code will trigger formatting upon save, which after handed over to terraform-ls means we run terraform fmt -. I can't think of many realistic cases where the fmt command itself (in isolation) would consume that much CPU (beyond a really large file). However I am aware that some people front Terraform binary with some wrapper scripts, or manage installation via other tooling, such as tfenv, which itself is known to delay any execution as per tfutils/tfenv#196

Were you able to reproduce this with a fresh installation from https://releases.hashicorp.com/terraform/ or any other official source (Homebrew Tap, Linux packages)?

If yes can you try disabling formatting in VS Code settings and see if that makes any change in CPU consumption on save?

    "[terraform]": {
        "editor.formatOnSave": false
    },

You can see this in the timestamps of the Gist I shared, where there's a message server.go:175: Processing 1 requests about once every second while I'm waiting for it to save.

This would suggest that #426 is indeed the root cause - i.e. the server has received multiple requests, but only processes a single one at a time in a blocking fashion. I do have a draft PR here #489 - I just need to read up a little bit more on the context of why did we decrease the concurrency and what exact problems we experienced in the past when concurrency was higher. Also I want to see if #504 can be implemented in the same PR to give users a little more control over this.

[btmills]

memory

#506 is interesting, thanks! 150-250MB isn't causing any memory pressure right now, but I do init locally, so if that opt-out does ship, I might enable it.

are you absolutely sure this amount of CPU is allocated by terraform-ls and not terraform?

Just double checked to confirm. This time, I typed a one-line comment, so ~60 chars, and did not save the file. Here's Activity Monitor:

ps doesn't show any terraform process active:

$ ps -ax | grep terraform
81018 ??        14:01.62 /Users/brandon/.vscode/extensions/hashicorp.terraform-2.10.2/lsp/terraform-ls serve
83702 ttys002    0:00.00 grep --color=auto --exclude-dir=.bzr --exclude-dir=CVS --exclude-dir=.git --exclude-dir=.hg --exclude-dir=.svn terraform

I waited for CPU usage to drop back down and the VSCode terraform-ls logs to finish. Then I hit save, and it finished quickly, producing these additional log messages:

2021/05/11 15:47:27 server.go:591: Received 1 new requests
2021/05/11 15:47:27 server.go:175: Processing 1 requests
2021/05/11 15:47:27 server.go:266: Checking request for "textDocument/formatting": {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf"},"options":{"tabSize":2,"insertSpaces":true}}
2021/05/11 15:47:27 rpc_logger.go:29: Incoming request for "textDocument/formatting" (ID 296): {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf"},"options":{"tabSize":2,"insertSpaces":true}}
2021/05/11 15:47:27 rpc_logger.go:50: Response to "textDocument/formatting" (ID 296): []
2021/05/11 15:47:27 server.go:247: Completed 1 requests [216.376903ms elapsed]
2021/05/11 15:47:27 server.go:591: Received 1 new requests
2021/05/11 15:47:27 server.go:175: Processing 1 requests
2021/05/11 15:47:27 server.go:266: Checking request for "textDocument/didSave": {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf","version":499}}
2021/05/11 15:47:27 rpc_logger.go:29: Incoming notification for "textDocument/didSave": {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf","version":499}}
2021/05/11 15:47:30 server.go:591: Received 1 new requests
2021/05/11 15:47:30 server.go:175: Processing 1 requests
2021/05/11 15:47:30 server.go:266: Checking request for "textDocument/codeLens": {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf"}}
2021/05/11 15:47:30 server.go:298: Task error: [-32601] no such method "textDocument/codeLens"
2021/05/11 15:47:30 rpc_logger.go:45: Error for "textDocument/codeLens" (ID 297): [-32601] no such method "textDocument/codeLens"
2021/05/11 15:47:30 server.go:247: Completed 1 requests [169.451µs elapsed]
[Error - 3:47:30 PM] Request textDocument/codeLens failed.
  Message: no such method "textDocument/codeLens"
  Code: -32601 

can you try disabling formatting in VS Code settings

With formatOnSave disabled, if I type a one-line comment and immediately save, the file saves immediately, and then I see high CPU usage from terraform-ls and logs in the VSCode output panel for the next minute or so. It appears you're correct that this has nothing to do with saving itself, and VSCode's "Saving 'file.tf': Running 'HashiCorp Terraform' Formatter" dialog is just a symptom of the language server still working through its queue before it can process the format request.

Were you able to reproduce this with a fresh installation

I just ran brew uninstall terraform, deleted the .terraformdirectory in case it helps, confirmed brew tap shows hashicorp/tap, ran brew install hashicorp/tap/terraform, ran terraform init, re-launched VSCode, and repeated the one-line comment test without saving. Same result. From starting VSCode, opening a .tf file, typing 46 characters, and waiting, terraform-ls is now sitting at 1:15.05 CPU time.

In the logs, I see 46 incoming textDocument/didChange notifications, each of which has a single character in its text value. They were processed between 16:11:05 and 16:11:54 at ~1/s. These logs repeat for each one:

2021/05/11 16:11:50 server.go:175: Processing 1 requests
2021/05/11 16:11:50 server.go:266: Checking request for "textDocument/didChange": {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf","version":44},"contentChanges":[{"range":{"start":{"line":0,"character":41},"end":{"line":0,"character":41}},"rangeLength":0,"text":"i"}]}
2021/05/11 16:11:50 server.go:448: Posting server notification "textDocument/publishDiagnostics" {"uri":"file://~/myapp/terraform/myapp.tf","diagnostics":[]}
2021/05/11 16:11:50 rpc_logger.go:29: Incoming notification for "textDocument/didChange": {"textDocument":{"uri":"file://~/myapp/terraform/myapp_production.tf","version":43},"contentChanges":[{"range":{"start":{"line":0,"character":40},"end":{"line":0,"character":40}},"rangeLength":0,"text":"n"}]}
2021/05/11 16:11:50 server.go:448: Posting server notification "textDocument/publishDiagnostics" {"uri":"file://~/myapp/terraform/myapp_staging.tf","diagnostics":[]}
2021/05/11 16:11:50 server.go:448: Posting server notification "textDocument/publishDiagnostics" {"uri":"file://~/myapp/terraform/main.tf","diagnostics":[]}
2021/05/11 16:11:50 server.go:448: Posting server notification "textDocument/publishDiagnostics" {"uri":"file://~/myapp/terraform/myapp_production.tf","diagnostics":[]}
2021/05/11 16:11:50 server.go:448: Posting server notification "textDocument/publishDiagnostics" {"uri":"file://~/myapp/terraform/drivecapital.tf","diagnostics":[]}
2021/05/11 16:11:50 module_loader.go:196: ML: enqueing "OpTypeParseConfiguration" module operation: ~/myapp/terraform
2021/05/11 16:11:50 module_loader.go:148: executing "OpTypeParseConfiguration" for ~/myapp/terraform
2021/05/11 16:11:50 module_loader.go:171: finished "OpTypeParseConfiguration" for ~/myapp/terraform
2021/05/11 16:11:50 module_loader.go:196: ML: enqueing "OpTypeLoadModuleMetadata" module operation: ~/myapp/terraform
2021/05/11 16:11:50 module_loader.go:148: executing "OpTypeLoadModuleMetadata" for ~/myapp/terraform
2021/05/11 16:11:51 module_loader.go:183: finished "OpTypeLoadModuleMetadata" for ~/myapp/terraform

This would suggest that #426 is indeed the root cause - i.e. the server has received multiple requests, but only processes a single one at a time in a blocking fashion.

Am I correct that concurrency was originally decreased in #120 with v0.3.0? Like the OP, because of signing I can't go back and check older versions to see exactly when this started, but I only noticed this ~10 days ago, so the v0.16.0 release seems like a likely candidate. I was definitely not experiencing this more than two weeks ago, so I suspect that this didn't occur in v0.15.0. I'm wondering if something else changed recently that caused caused serial requests to become an issue a couple weeks ago after having been fine by themselves for several releases.

[radeksimko]

0.16.2 and 0.16.3 were released recently with patches that should address the two discussed problems, as long as the assumptions about the root causes were correct. You should receive the update automatically if you use the Terraform VS Code extension.

#489
#488

There is another issue to be yet resolved to address another potential source of CPU spikes:
#509

With that in mind I'm going to close this issue, but please do let us know if you experience any similar issue in the future via new issue. Attaching CPU profiles to such issues (where high CPU is a symptom) would also be incredibly helpful and would likely help understand the problem and fix it in a timely manner.

[ekristen]

Unfortunately this is no where fixed for me. How do I tell vscode to run with the CPU profiles for the language server since vscode installs and runs it? Those instructions seem to be missing from the troubleshooting guide?

I honestly think it's worse than before. I'm running on a Macbook Pro 2019 64GB of RAM and when I write a lot of terraform code, I end up waiting MINUTES unless I kill the language server and/or the formatter to get it to save :/

[radeksimko]

That last patch I mentioned (for #509 ) was not released yet - we plan to release it this week though.

Those instructions seem to be missing from the troubleshooting guide?

You can find some relevant docs on how to change settings of the extension, including how the LS is launched here https://github.com/hashicorp/vscode-terraform/wiki/Manually-Setting-the-Terraform-Executable-Path

[danieldreier]

I'm going to re-open this since we haven't released the #509 patch, which we are hoping will help here. @ekristen when that's released this week, please let us know whether the new language server version helps. If not, please let us know and we can schedule a troubleshooting session.

[ekristen]

I've adjusted my path, but the log files have remained at 0 bytes all day long.

[radeksimko]

@ekristen The CPU profile is written upon shutdown, i.e. when you close VS Code and that instructs the LS to shut down and write the CPU profile to disk.

[radeksimko]

I have just shipped 0.17.1 - can you please try upgrading and confirm that this resolved mentioned issues?

VS Code should show prompt automatically within the next 24 hours or upon launch.

[btmills]

After working in our Terraform configuration a bunch today, I'm happy to report that I didn't notice any of the slowness I was seeing before. Thanks for fixing it!

[radeksimko]

That is great to know, thanks for confirming!

I'm going to close this issue now but please let us know by opening a new issue and collecting the CPU profile, as mentioned.

[ekristen]

It definitely seems to be way better. Thank you!

[github-actions]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.