Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

x/tools/gopls: don't hang in allImportsFixes #59216

Closed
findleyr opened this issue Mar 24, 2023 · 19 comments
Closed

x/tools/gopls: don't hang in allImportsFixes #59216

findleyr opened this issue Mar 24, 2023 · 19 comments
Assignees
Labels
gopls/imports gopls Issues related to the Go language server, gopls. okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 Tools This label describes issues relating to any tools in the x/tools repository.
Milestone

Comments

@findleyr
Copy link
Contributor

Thanks to the newly improved trace view, I have noticed that sometimes my gopls gets into a state where it hangs behind 'allImportFixes'. I expect this is the source of the often reported bug of 'waiting for code actions' from VS Code

Sample trace below, where AllImportsFixes took 3s for x/tools. (by comparison, type-checking all of x/tools from scratch takes ~3s).

16:11:59.594 end textDocument/codeAction (+3.682277772s) method="textDocument/codeAction" direction="in" id="#168"
16:11:59.594 event (+3.682275217s) label= status.code="OK"
16:11:55.912 start queued
16:11:55.912 end queued (+76.801µs)
16:11:55.912 start source.AllImportsFixes
16:11:59.528 end source.AllImportsFixes (+3.616084629s)
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/fs_memoized.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/analysis.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/debug.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/workspace.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/cache.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/errors.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/parse.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/fs_overlay.go"
16:11:59.529 end cache.parseGo (+208.039µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/debug.go"
16:11:59.529 end cache.parseGo (+219.166µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/cache.go"
16:11:59.529 end cache.parseGo (+177.206µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/fs_overlay.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/check.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/snapshot.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/graph.go"
16:11:59.530 end cache.parseGo (+390.728µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/fs_memoized.go"
16:11:59.530 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/pkg.go"
16:11:59.530 end cache.parseGo (+476.13µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/workspace.go"
16:11:59.530 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/parse_cache.go"
16:11:59.530 end cache.parseGo (+312.913µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/graph.go"
16:11:59.530 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/imports.go"
16:11:59.530 end cache.parseGo (+341.08µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/pkg.go"
16:11:59.530 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/session.go"
16:11:59.530 end cache.parseGo (+440.109µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/imports.go"
16:11:59.530 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/keys.go"
16:11:59.530 end cache.parseGo (+192.499µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/keys.go"
16:11:59.530 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/load.go"
16:11:59.531 end cache.parseGo (+877.609µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/parse_cache.go"
16:11:59.531 end cache.parseGo (+1.356713ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/errors.go"
16:11:59.531 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/symbols.go"
16:11:59.531 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/mod.go"
16:11:59.531 end cache.parseGo (+501.887µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/symbols.go"
16:11:59.531 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/standalone_go116.go"
16:11:59.531 end cache.parseGo (+1.926097ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/parse.go"
16:11:59.529 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/packageset.go"
16:11:59.531 end cache.parseGo (+166.758µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/standalone_go116.go"
16:11:59.531 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/maps.go"
16:11:59.531 end cache.parseGo (+2.185366ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/packageset.go"
16:11:59.531 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/view.go"
16:11:59.532 end cache.parseGo (+268.718µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/maps.go"
16:11:59.532 end cache.parseGo (+1.605985ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/session.go"
16:11:59.532 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/walkdecl.go"
16:11:59.532 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/mod_tidy.go"
16:11:59.532 end cache.parseGo (+2.454171ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/analysis.go"
16:11:59.532 start cache.parseGo file="/home/rfindley/src/tools/gopls/internal/lsp/cache/mod_vuln.go"
16:11:59.532 end cache.parseGo (+1.265517ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/mod.go"
16:11:59.532 end cache.parseGo (+203.7µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/mod_vuln.go"
16:11:59.532 end cache.parseGo (+1.51323ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/load.go"
16:11:59.532 end cache.parseGo (+2.841495ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/check.go"
16:11:59.532 end cache.parseGo (+789.382µs) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/mod_tidy.go"
16:11:59.533 end cache.parseGo (+1.058849ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/walkdecl.go"
16:11:59.533 end cache.parseGo (+3.722685ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/snapshot.go"
16:11:59.533 end cache.parseGo (+1.760966ms) file="/home/rfindley/src/tools/gopls/internal/lsp/cache/view.go"

I don't think we should ever wait a significant amount of time for allImportsFixes. goimports is already imprecise and/or nondeterministic, depending on the state of the module cache.

@findleyr findleyr added this to the gopls/v0.12.0 milestone Mar 24, 2023
@gopherbot gopherbot added Tools This label describes issues relating to any tools in the x/tools repository. gopls Issues related to the Go language server, gopls. labels Mar 24, 2023
@findleyr findleyr added release-blocker okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 labels Apr 17, 2023
@findleyr findleyr self-assigned this May 4, 2023
@gopherbot
Copy link

Change https://go.dev/cl/492679 mentions this issue: gopls/internal/lsp/cache: always init the resolver in runProcessEnvFunc

gopherbot pushed a commit to golang/tools that referenced this issue May 5, 2023
The current logic populates the process env *after* clearing, but
clearing uses fields in the process env. To work around this, clearing
is not performed on the first run.

Chesterton's fence may apply: I don't really understand this, but don't
see how it could be correct: if the clearing requires the environment,
then the environment should be populated before clearing.

For golang/go#59216

Change-Id: Ia0bc0de10284abf9853158e4f7e60de3d338083d
Reviewed-on: https://go-review.googlesource.com/c/tools/+/492679
Reviewed-by: Alan Donovan <adonovan@google.com>
gopls-CI: kokoro <noreply+kokoro@google.com>
Run-TryBot: Robert Findley <rfindley@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
@gopherbot
Copy link

Change https://go.dev/cl/494095 mentions this issue: gopls: additional instrumentation during goimports

gopherbot pushed a commit to golang/tools that referenced this issue May 10, 2023
Add some visibility into goimports operations, by instrumenting spans in
top-level imports and gocommand operations.

This may be the first time we instrument non-gopls code in this way, but
it should be safe as other build targets (e.g. the goimports or
gopackages commands) do not set a global exporter, and therefore the
cost of event instrumentation should be minimal.

For golang/go#59216

Change-Id: Id2f8fe05d6b61e96cdd2d41cc43b3d4c3cf39e21
Reviewed-on: https://go-review.googlesource.com/c/tools/+/494095
Reviewed-by: Alan Donovan <adonovan@google.com>
Run-TryBot: Robert Findley <rfindley@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
gopls-CI: kokoro <noreply+kokoro@google.com>
@findleyr
Copy link
Contributor Author

Just encountered this again, and the new instrumentation narrows this down to addExternalCandidates:

10:28:06.893 end source.AllImportsFixes (+4.861670795s)
10:28:02.032 start cache.importsState.runProcessEnvFunc
10:28:06.893 end cache.importsState.runProcessEnvFunc (+4.86163328s)
10:28:02.032 start imports.FixImports
10:28:06.893 end imports.FixImports (+4.861465307s)
10:28:02.041 start imports.addExternalCandidates
10:28:06.893 end imports.addExternalCandidates (+4.852100098s)

@findleyr
Copy link
Contributor Author

While this is still a problem, it seems like it only hangs for perhaps 5-10 seconds. The real culprit of hanging in code actions was discovered, and fixed in https://go.dev/cl/496186.

goimports isn't going to get rewritten for v0.12.0. Moving to v0.13.0, when hopefully we'll have time to unify goimports and unimported completion, and have a better handle on its execution.

@findleyr
Copy link
Contributor Author

findleyr commented Nov 9, 2023

Just hit this again:

13:07:20.584 end imports.FixImports (+11.747050334s)
13:07:08.857 start imports.addExternalCandidates
13:07:20.584 end imports.addExternalCandidates (+11.72726959s)

@ldemailly
Copy link

I have this problem too when something goes wrong it hangs

image

where do I see that debug log?

@vikblom
Copy link

vikblom commented Nov 16, 2023

@ldemailly If you start gopls with the argument --debug=localhost:6060 then you can see the traces in your browser. See gopls troubleshooting, and since it looks like you are using VS Code: vscode-go settings.

@vikblom
Copy link

vikblom commented Nov 16, 2023

It happened to me today

imports.FixImports
Last

    14:50:00.290 end imports.FixImports (+786.542µs)

Longest

    14:50:00.198 end imports.FixImports (+39.213127084s)
        14:49:21.004 start imports.addExternalCandidates
        14:50:00.198 end imports.addExternalCandidates (+39.19372275s)

My only guess would be that I have lots of packages on GOPATH that take time to load, if that even is a thing.

Would it make sense to add more instrumentation to narrow this down?

@findleyr
Copy link
Contributor Author

Would it make sense to add more instrumentation to narrow this down?

Absolutely. Now that we have a few people tracking this, I think it makes sense to add more spans to see where the time is being spent (goimports code is not instrumented in the same way as the rest of gopls).

@vikblom how frequently do you hit this? I seem to get it only ~once a month, so it has been hard to catch.

@vikblom
Copy link

vikblom commented Nov 16, 2023

Roughly once a week but it varies a lot. In my experience it happens more often when I'm working in many different repos and adding/removing dependencies. Probably just because that exercises this codepath more.

@ldemailly
Copy link

for me it's more like a daily (several times today actually) it hangs each time I have a new import/compilation error

@gopherbot
Copy link

Change https://go.dev/cl/544515 mentions this issue: gopls/internal/lsp/cache: don't rebuild filters for each modcache dir

gopherbot pushed a commit to golang/tools that referenced this issue Nov 27, 2023
While investigating a post-review comment on CL 538796, I observed that
the importsState.SkipPathInScan func is building a directory filterer
for every call. This can be very expensive, and may partially explain
the performance problems encountered in golang/go#59216.

Fix this, and update the test to catch bugs related to mixing up relpath
vs abspath (a mistake I made during this CL).

Updates golang/go#59216

Change-Id: I696429161ba039a380df1cf258edf78369acb398
Reviewed-on: https://go-review.googlesource.com/c/tools/+/544515
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
Auto-Submit: Robert Findley <rfindley@google.com>
@findleyr
Copy link
Contributor Author

findleyr commented Jan 16, 2024

Just had allImportFixes take 34s, the longest I've seen by an order of magnitude, so this is definitely not fixed :(
(Edit: as a point of reference I experienced this immediately after opening my laptop, which may affect both contention and perhaps interact negatively with the background process env refresh timer).

@vikblom
Copy link

vikblom commented Jan 19, 2024

For anyone that stumbles across this issue. On my system this was made worse (or was caused) by an oversized GOPATH (check du -sh ~/go).

Running go clean -modcache can help reduce pressure while waiting for a more permanent fix.

@gopherbot
Copy link

Change https://go.dev/cl/559496 mentions this issue: gopls/internal/cache/imports: simplify importsState invalidation

gopherbot pushed a commit to golang/tools that referenced this issue Jan 31, 2024
Now that views are immutable, we can simplify the invalidation of
imports state. The imports.ProcessEnv can also be immutable, and we need
only invalidate module state (i.e. dependencies) if a go.mod file
changes.

While at it, add documentation and perform some superficial cleanup in
the internal/imports package. This is a first step toward larger state
optimizations needed for the issues below. TODOs are added for remaining
work.

For golang/go#44863
For golang/go#59216

Change-Id: I23c1ea96f241334efdbfb4c09f6265637b38f497
Reviewed-on: https://go-review.googlesource.com/c/tools/+/559496
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
@gopherbot
Copy link

Change https://go.dev/cl/559458 mentions this issue: internal/imports: fix modCacheRegexp.FindStringSubmatch condition

@gopherbot
Copy link

Change https://go.dev/cl/559635 mentions this issue: internal/imports: merge init and newModuleResolver

@gopherbot
Copy link

Change https://go.dev/cl/561235 mentions this issue: gopls/internal/cache: prime goimports cache asynchronously

gopherbot pushed a commit to golang/tools that referenced this issue Feb 6, 2024
Switch the ModuleResolver from a lazy initialization model to a
constructor, so that the resolver returned by ProcessEnv.GetResolver is
ready to use.

A constructor is easier to maintain as it involves less state, avoids
redundant calls to init, and avoids bugs where the call to init is
missing (such as was the case for the scoreImportPath method). It also
lets the caller differentiate between a failure to construct the
resolver and a resolver that only returns errors.

Pragmatically, I'd like to move toward a model where the caller re-scans
imports by asynchronously cloning, priming, and replacing the resolver,
rather than blocking. This is a step in that direction.

This change is not without risk, but it looks like all calls to
ModuleResolver methods are preceded by a call to GetResolver, and
errors from GetResolver are handled similarly errors from methods.

There is some messiness resulting from this change, particularly in
tests. These are noted inline, and can eventually be fixed by similarly
avoiding lazy initialization of ProcessEnv.

For golang/go#59216

Change-Id: I3b7206417f61a5697ed83e811c177f646afce3b2
Reviewed-on: https://go-review.googlesource.com/c/tools/+/559635
Reviewed-by: Alan Donovan <adonovan@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
@findleyr
Copy link
Contributor Author

findleyr commented Feb 6, 2024

This should be fixed at tip, since we now run goimports on the old cache until the new cache is ready. Please let me know if it's not fixed in your environment.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
gopls/imports gopls Issues related to the Go language server, gopls. okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Development

No branches or pull requests

4 participants