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

[findleyr]

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.

[gopherbot]

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

[gopherbot]

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

[findleyr]

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]

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.