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

Closed
myitcv opened this issue Jun 24, 2019 · 34 comments
Closed

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

myitcv opened this issue Jun 24, 2019 · 34 comments
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@myitcv
Copy link
Member

myitcv 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

@myitcv myitcv added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. gopls Issues related to the Go language server, gopls. labels Jun 24, 2019
@gopherbot gopherbot added this to the Unreleased milestone Jun 24, 2019
@bmhatfield
Copy link

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
Copy link
Contributor

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

@heschi
Copy link
Contributor

heschi 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
Copy link

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
Copy link
Contributor

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

@bmhatfield
Copy link

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

@stamblerre
Copy link
Contributor

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
Copy link

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link

bmhatfield 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
Copy link
Contributor

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
Copy link

bmhatfield 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
Copy link
Contributor

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
Copy link

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

@bmhatfield
Copy link

bmhatfield 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
Copy link
Contributor

@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
Copy link

s-kostyaev 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
Copy link
Contributor

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

@s-kostyaev
Copy link

s-kostyaev commented Jul 1, 2019

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

@s-kostyaev
Copy link

s-kostyaev commented Jul 1, 2019

gopls-stderr.log
it panics

@stamblerre
Copy link
Contributor

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
Copy link

s-kostyaev 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
Copy link

@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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link

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
Copy link
Member Author

myitcv commented Aug 20, 2019

@heschik @suzmue - any update on this? Thanks

@suzmue
Copy link
Contributor

suzmue commented Aug 20, 2019

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.

@suzmue suzmue assigned heschi and unassigned suzmue Aug 30, 2019
@myitcv
Copy link
Member Author

myitcv commented Sep 5, 2019

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
Copy link
Member Author

myitcv commented Sep 5, 2019

Will continue conversation in #34111

@stamblerre
Copy link
Contributor

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
Copy link
Member Author

myitcv commented Sep 5, 2019

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
Copy link
Contributor

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

@golang golang locked and limited conversation to collaborators Sep 4, 2020
@rsc rsc unassigned heschi Jun 23, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

8 participants