x/tools/gopls: imports extremely slow with large module cache

[myitcv]

What version of Go are you using (go version)?

$ go version
go version devel +44c9354c5a Fri Jun 21 05:21:30 2019 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20190620191750-1fa568393b23
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.0.0-20190620191750-1fa568393b23

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN="/home/myitcv/gostuff/src/github.com/myitcv/govim/cmd/govim/.bin"
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/gostuff/src/github.com/myitcv/govim/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build977371100=/tmp/go-build -gno-record-gcc-switches"

What did you do?

The issue I keep tripping across is making refactoring changes that, for example, rename variables. If I fail to rename all instances of the variable (perhaps I've copy-pasted some code from somewhere), there's a chance I've left behind a selector expression with the old variable name... which is now treated by imports as if it were a qualified identifier for a package that has not yet been imported.

Like #32726, imports then heads off into the module cache searching through all potential matches. With a 5GB module cache, this is not a quick operation.

I think imports should:

• pre-load and cache its results from the module cache
• have that cache be invalidated where the modification time of any non-module cache-based go.{mod,sum} reachable from the main module changes
• when the cache is invalidated, re-warm the cache in the background

Yes, this will cause possibly stale results in the case that another main module causes changes in the module cache, but I think that's a sacrifice worth making for the general speed of imports.

What did you expect to see?

Instant responses to imports-based format-on-save.

What did you see instead?

~10sec delays.

---

cc @stamblerre @ianthehat @heschik

[bmhatfield]

Is there a command I can run on my machine to demonstrate if I am experiencing this? I only have a 250MB module cache, but imports take 30-45s on my machine at least. I do have a likely somewhat larger than normal repo with many packages in it, however.

[stamblerre]

Do you see this kind of latency when you run goimports via the command line or is it only when gopls invokes it?

[heschi]

@bmhatfield Run goimports -v on the file and see how long it's taking to do directory scans. It should be pretty clear from the output but if not attach it here and I'll take a look.

[bmhatfield]

I took a file that was having difficulty performing imports (30-45s in vscode "running save participants") and never actually completing the imports. I edited it into a state where VSCode reliably is sluggish and fails to perform imports/formatting (by deleting 3 import lines).

goimports -v runs in less than a second and the output contains the correct imports.

[stamblerre]

Do you see similar latencies with other gopls features, like jump to definition or autocomplete?

[bmhatfield]

Jump to definition: 2-3s latencies, with a blue "processing bar" that moves across the top of the window.
Autocomplete: feels instant.

[stamblerre]

Wow, that's a very strange range of latencies. Definition should definitely feel instant as well. I would have expected every feature to be slow rather than some, and then even so, it seems like go-to-definition is still faster than imports. Do you mind sharing a full gopls log (View: Debug Console -> Output -> Tasks -> gopls) just so I can get a fuller picture?

[bmhatfield]

Happy to - should we migrate this conversation to #32360, given that I am not experiencing the "large module cache" issue? Or prefer here still?

[josharian]

Purely anecdotal, but I have also experienced normal gopls response times for everything but goimports. (I fear I am AFK for a while, so can’t help reproduce/debug.)

[stamblerre]

Either is fine as these all seem to be general imports related issues, so whichever you prefer. We are in the process of adding a lot more tracing and debug information, so it's possible we won't be able to get to the bottom of the issue until all of that is submitted.

[bmhatfield]

Hrm. There appears to be no output in the gopls window during Jump To Definition or during the "Running Save Participants" phase.

[stamblerre]

Oh, I'm sorry I forgot to mention that you should add -rpc.trace to your "go.languageServerFlags" setting. You can also look at additional debug info by configuring your settings according to https://github.com/golang/go/wiki/gopls#troubleshooting.

[bmhatfield]

Apologies, that's on me. You've mentioned this in other issues I'm active in.

{gist link removed}

In this particular case, I restarted VSCode before capturing the log, and things were "faster" at 8.5s for imports, though the imports never actually materialized in VSCode (ie, the code to be imported was still undefined symbol errors).

I also code navigated towards the end of the log but it wasn't as slow in this particular case as it sometimes is, though you can see other timings are a bit all over the place.

I am happy to continue gathering logs as needed.

EDIT: for reference:

"editor.codeActionsOnSaveTimeout": 60000,
    "editor.formatOnSaveTimeout": 60000,

[stamblerre]

Thank you for sharing. The times here are really strange - it seems like imports starts out working at ~1 second as expected, and then somehow gets to 8 seconds, which causes the subsequent requests to stall (there is no reason for documentLink to ever take 8 seconds, as it does at one point in the log).

Can you try setting the Debug variable in https://godoc.org/golang.org/x/tools/imports#pkg-variables to true and rebuilding gopls with that? Those logs might indicate where imports is spending its time. More likely than not, however, gopls is getting stuck somewhere, perhaps doing go list. Also, worth asking, does your package use cgo?

[bmhatfield]

We don't use cgo directly, I also believe that none of our dependencies use cgo.

[bmhatfield]

Added an updated log to that gist. (Gist link removed because it appears to contain somewhat sensitive code - @stamblerre is there a way to send you this more privately?)

I believe I successfully rebuilt gopls with debug on. I checked out the 0.1.1 branch first. Apologies in advance if I've set myself up wrong.

[stamblerre]

@bmhatfield: If you are willing to share these logs with me, I am reachable on the Gophers Slack (https://invite.slack.golangbridge.org/) or you can send me an email at [email protected].

Is anyone else experiencing a similar issue? It would be useful to see if this is a common problem or an issue specific to your setup. I have sent out a CL to add additional logging for goimports in gopls (https://go-review.googlesource.com/c/tools/+/184198).

[s-kostyaev]

I have same issue. Gopls is frozen when I try to add new import. In other cases it works fine.

[stamblerre]

@s-kostyaev: Are you able to share your gopls logs when this happens?

[s-kostyaev]

Ok, I'll try to reproduce it on non sensitive data.

[s-kostyaev]

gopls-stderr.log
it panics

[stamblerre]

Can you sync to master (go get -u golang.org/x/tools/gopls@master)? I just submitted a fix for this nil pointer.

[s-kostyaev]

Thanks. It stops freezing. And panic is also fixed.

[bmhatfield]

@stamblerre Just checking in here - is there further information I can gather to be helpful? I believe you mentioned that there's additional logging/tracing that will land soon - is that ready for me to gather more data with?

[stamblerre]

I did submit a change that turned the imports debug logging on by default: https://go-review.googlesource.com/c/tools/+/184198.
We are also working on further improvements to imports, which can be tracked by looking at the issues tagged gopls-imports: https://github.com/golang/go/issues?utf8=%E2%9C%93&q=is%3Aissue+is%3Aopen+label%3Agopls-imports.
The additional tracing work is still in progress.

[stamblerre]

Actually, @bmhatfield, can you share logs using imports with the latest version of gopls (go get golang.org/x/tools/gopls@latest)? I added some additional logging in the CL I linked above.

[bmhatfield]

Chiming in here to say I've been staying reasonably current on gopls and things seem to be working much better for me now. I can't pinpoint the exact time things got better, but I haven't had a case of getting stuck importing and needing to resolve by hand for at least a week.

[myitcv]

@heschik @suzmue - any update on this? Thanks

[suzmue]

We have started reusing the imports resolver in gopls (https://golang.org/cl/184921) and added some caching of packages in the module cache (https://golang.org/cl/186301), which both work to speed up imports when there have been no go.mod file changes.

A new caching design is currently being implemented to avoid repeat work of scanning the module cache.

Pre-warming of this cache has not been implemented yet.

[myitcv]

Thanks. See some benefits here as a result of https://golang.org/cl/184921 and https://golang.org/cl/186301.

Pre-warming of this cache has not been implemented yet.

This will also help. However, for Vim users (via whatever plugin) this will also likely become something of a pain. Because Vim users typically start/stop Vim regularly, especially when used from the terminal. Hence, if gopls is being started/stopped each time (communicating over stdin/stdout) then every time Vim is started (and there are often multiple instances of Vim open) this pre-warming will happen.

So any pre-warming will, I suspect, need to go hand-in-hand with ensuring the socket-based communication with gopls is on a par with the pipe-based approach. I would guess it is, but cc @stamblerre and @ianthehat for thoughts?

[myitcv]

Will continue conversation in #34111

[stamblerre]

Sounds good. @myitcv: Do you feel that this issue has been resolved enough that we can close this? (We can track future imports improvements in other issues.)

[myitcv]

Do you feel that this issue has been resolved enough that we can close this?

I think the final piece in the puzzle is probably:

Pre-warming of this cache has not been implemented yet.

But I think that only makes sense post #34111 for the reasons laid out in that description.

So yes, can probably close this if we create a follow up issue for the pre-warming of the cache, an issue that is contingent on #34111

[stamblerre]

Sounds good. Closing this and filed #34115 to track pre-warming the cache.