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: imports extremely slow with large module cache #32750

Open
myitcv opened this issue Jun 24, 2019 · 26 comments

Comments

Projects
None yet
8 participants
@myitcv
Copy link
Member

commented Jun 24, 2019

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

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

@heschik

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

@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

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

@bmhatfield

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

@stamblerre

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

@stamblerre

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

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

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

@bmhatfield

This comment has been minimized.

Copy link

commented Jun 28, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jun 28, 2019

@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 rstambler@golang.org.

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

This comment has been minimized.

Copy link

commented Jun 29, 2019

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

@stamblerre

This comment has been minimized.

Copy link
Contributor

commented Jul 1, 2019

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

@s-kostyaev

This comment has been minimized.

Copy link

commented Jul 1, 2019

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

@s-kostyaev

This comment has been minimized.

Copy link

commented Jul 1, 2019

gopls-stderr.log
it panics

@stamblerre

This comment has been minimized.

Copy link
Contributor

commented Jul 1, 2019

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

This comment has been minimized.

Copy link

commented Jul 1, 2019

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

@stamblerre stamblerre changed the title x/tools/cmd/gopls: imports extremely slow with large module cache x/tools/gopls: imports extremely slow with large module cache Jul 2, 2019

@bmhatfield

This comment has been minimized.

Copy link

commented Jul 9, 2019

@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

This comment has been minimized.

Copy link
Contributor

commented Jul 10, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Jul 10, 2019

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.