High CPU utilization at almost every save

[wtask]

What version of Go, VS Code & VS Code Go extension are you using?

• Run go version to get version of Go
  • go version go1.14 windows/amd64
• Run code -v or code-insiders -v to get version of VS Code or VS Code Insiders
  • Version: 1.43.0 (user setup)
    Commit: 78a4c91400152c0f27ba4d363eb56d2835f9903a
    Date: 2020-03-09T19:47:57.235Z
    Electron: 7.1.11
    Chrome: 78.0.3904.130
    Node.js: 12.8.1
    V8: 7.8.279.23-electron.0
    OS: Windows_NT x64 10.0.18363
• Check your installed extensions to get the version of the VS Code Go extension
  • 0.13.1

Describe the bug

I have a project with different workspace folders. Very often after making some changes I press Ctrl+S. And after that my laptop begins execute very hard job which consumes 100% CPU utilization. I don't understand which the underlying tasks are running by vscode-go extension at this moment, but 4 cores with 32 Gb RAM works very slow and make me crazy why the file saving is for 3-4 minutes. Also, I see an abnormal behaviour of Windows Defender when vscode-go is saving file. Perhaps the Antimalware Service Executable does not trust for gopls-processes.

Screenshots or recordings

[hyangah]

@wtask It seems that gopls is using quite bit of memory and cpu.
Can you try the settings to capture traces from gopls?
https://github.com/golang/tools/blob/master/gopls/doc/vscode.md#vscode

"go.languageServerFlags": [
    "-rpc.trace", // for more detailed debug logging
    "serve",
    "--debug=localhost:6060", // to investigate memory usage, see profiles
]

@stamblerre

[wtask]

@hyangah I updated my settings.json according to the latest wiki recommendations. Also I added language server flags. Also I put gopls.exe into Windows Defender exclusion. Need to observe.

[stamblerre]

If you are working on a public project, could you share a link to the repository so we can try to repro? gopls may behave badly on a repository with a lot of packages and dependencies.

[wtask]

@stamblerre GOPRIVATE is set for this project

[tobiaszheller]

@stamblerre I can also confirm bug.

It can be observer with latest relase of gopls as well as version from master.
What is weird that I have started seeing it after updating vs-code, not gopls.

I think it can be related to case when you have modules enabled but still vendor exists in project.
You can verify it at https://github.com/thanos-io/thanos/ project.
Just do new line in cmd/thanos/rule.go and save it (with format on save setting). It will work without any issues.
However if you run go mod vendor and then trying to save it once again, it will run like forever without saving it.

[hyangah]

@tobiaszheller thanks for sharing the repro case.

@stamblerre here is the gopls log
thanos.log
I triggered save after the first logged textDocument/codeAction event. I noticed repro is a bit nondeterministic, probably, depending on the module, build cache state.

Related - we got another issue related the behavior change during file save after upgrade of vs code (1.43). The other issue was closed because it was due to another extension, but I wonder if there was a change in VS Code's save function and that tickled underlying issues.

[anykine29]

Wanted to leave a note about the output i see from gopls on save events -- which only started happening after the upgrade.
If i try to save a file here is what the gopls log outputs
[Trace - 09:40:28.757 AM] Sending notification 'textDocument/didChange'.
[Trace - 09:40:28.757 AM] Sending request 'textDocument/codeAction - (1810)'.
[Trace - 09:40:28.760 AM] Received response 'textDocument/codeAction - (1810)' in 2ms.
[Trace - 09:40:28.761 AM] Sending request 'textDocument/formatting - (1811)'.
[Trace - 09:40:28.763 AM] Received response 'textDocument/formatting - (1811)' in 1ms.
[Trace - 09:40:28.767 AM] Sending notification 'textDocument/didChange'.
[Trace - 09:40:28.767 AM] Sending request 'textDocument/codeAction - (1812)'.
[Trace - 09:40:28.769 AM] Received response 'textDocument/codeAction - (1812)' in 2ms.

and it does this constantly causing high load and crashes the window most of the time.

cat /var/tmp/gopls | egrep '\[Trace' | egrep '9:4' | wc -l
10123

My System:
Version: 1.43.0
Commit: 78a4c91400152c0f27ba4d363eb56d2835f9903a
Date: 2020-03-09T19:34:44.548Z
Electron: 7.1.11
Chrome: 78.0.3904.130
Node.js: 12.8.1
V8: 7.8.279.23-electron.0
OS: Darwin x64 19.2.0

{
"editor.fontSize": 16,
"window.zoomLevel": -1,
"explorer.confirmDragAndDrop": false,
"go.useLanguageServer": true,
"go.formatTool": "goimports",
"yaml.customTags": [
"!Base64 mapping",
"!Cidr sequence",
"!FindInMap sequence",
"!GetAtt",
"!GetAZs",
"!ImportValue",
"!Join sequence",
"!Ref",
"!Select sequence",
"!Split sequence",
"!Sub",
"!Transform mapping",
"!Not sequence",
"!Equals sequence",
"!And",
"!And sequence",
"!If",
"!If sequence",
"!Not",
"!Equals",
"!Or",
"!Or sequence",
"!FindInMap",
"!Base64",
"!Join",
"!Cidr",
"!Sub sequence",
"!ImportValue sequence",
"!Select",
"!Split"
],
"yaml.validate": false,
"editor.formatOnSave": true,
"[go]": {
"editor.formatOnSave": true,
"editor.codeActionsOnSave": {
"source.organizeImports": true,
},
// Optional: Disable snippets, as they conflict with completion ranking.
"editor.snippetSuggestions": "none",
},
"[go.mod]": {
"editor.formatOnSave": true,
"editor.codeActionsOnSave": {
"source.organizeImports": true,
},
},
"go.languageServerFlags": [
"-rpc.trace", // for more detailed debug logging
"serve",
"--debug=localhost:6060", // to investigate memory usage, see profiles
],
"gopls": {
// Add parameter placeholders when completing a function.
"usePlaceholders": true,
// If true, enable additional analyses with staticcheck.
// Warning: This will significantly increase memory usage.
"staticcheck": false,
}
}

[wtask]

@tobiaszheller In my case there are neither vendor folders inside project dirs

[hyangah]

@anykine29 Are all those 10123 lines the log messages after the file save? Can you share that output? I think we need to ask vscode team. I see some issue reports coming in to microsoct/vscode issue tracker, related to the behavior changes on save, but better trace data may help for them to triage.
@wtask can you also capture the gopls logs if possible and share it?

[anykine29]

Correct those 10k lines are as I try to save the file.

gopls.log

[wtask]

@hyangah I cannot publish current log due to project specific requirements. But in the log I saw tons of dummy gopls-processing with files in the .history/ folder. So the current issue may be related to #3036 (workspace/didChangeWatchedFiles). I have to disable the Local history extension and move .history folders out of project tree until any progress for #3036 will appear...

[hyangah]

@anykine29 thanks! I filed a new upstream issue based on your trace. Are you using any other go extension by any chance?

@stamblerre The trace I generated using @tobiaszheller's repro case exhibits a different issue and I want gopls-devs to take a look. It shows significant slow down after background refresh.

background refresh: 5sec
textDocument/codeLens: 76sec
textDocument/documentLink: 76sec
...

[anykine29]

@hyangah Thanks! And here are my go ext:

[hyangah]

@anykine29 thanks - according to #3109, Go Group Imports extension may be problematic. The gopls-debug can be disabled too (that's a test version of Go extension and doesn't add additional functionalities other than what Go extension offers already). I don't know much about other extensions, but turning on one by one until the problem reappears is one option for debugging.

[tobiaszheller]

@hyangah I was also using Go Group Imports extension, but the issue still exists, even though extension was disabled. I have also checked and there were not changes to that extension since December.

I guess something (vscode?) is triggering a lot of new events what's causing those extension to run all the time.

[stamblerre]

Sorry for not being more active on this issue - just trying to parse through the different cases here.

@anykine29: This issue does sound like the bug with Go Group Imports. Please let us know if disabling that extension resolved the issue (you can get similar behavior with gopls's local setting). If it doesn't, please open a new issue.

@wtask: Does disabling the Local History extension completely resolve the problem? If so, then this issue sounds like a duplicate of #3036 as you said. I'd recommend following along with golang/go#37697 for updates on that issue. Hopefully we will be able to come up with a reasonable approach for future gopls releases.

@tobiaszheller:

@hyangah I was also using Go Group Imports extension, but the issue still exists, even though extension was disabled. I have also checked and there were not changes to that extension since December.

Yes, there have been some changes in the way that VS Code handles on-save actions.

I tried to reproducing this issue, and I think the problem is simply that running go mod vendor produces a huge number of new files, which gopls then tries to run diagnostics on. The code action doesn't get executed because gopls is still loading all of the vendored packages, which overwhelms the server. I think the correct approach here would be to ignore vendor directories when we run diagnostics. I filed golang/go#38080 to track this upstream. Thank you for the report!

[wtask]

@stamblerre Sometimes I see the code actions popup for a few seconds, but the critical delay has disappeared

[stamblerre]

Thanks for letting me know! I've seen that pop-up myself a few times, so I'll try to do some more investigating when I see it next. If you see any code action requests that take longer than you'd expect, please report them.

[lazdmx]

Same problem. Just want to share my observation that the problem rises when working with even trivial Bazel-workspaces. I think that for proper operation all bazel-* directories must be excluded from processing by Go extension

[stamblerre]

@lazdmx: Right now, we don't officially support Bazel in gopls (see golang/go#37205), so it is likely that things won't work properly. Please file an issue here if you'd like me to investigate your specific case.

[vscodebot]

This issue has been closed automatically because it needs more information and has not had recent activity. Thank you for your contributions.

[stamblerre]

I'm going to leave this issue closed, but please file new issues if you encounter this problem. It's easier to help people individually. #3063 and #3105 are tracking the code action pop-ups.