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: Request to decrease or make configurable background import refresh frequency #44701

Open
jspawar opened this issue Mar 1, 2021 · 6 comments

Comments

@jspawar
Copy link

@jspawar jspawar commented Mar 1, 2021

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

$ go version
go version go1.15.6 darwin/amd64

$ gopls version
golang.org/x/tools/gopls v0.6.6
    golang.org/x/tools/gopls@v0.6.6 h1:GmCsAKZMEb1BD1BTWnQrMyx4FmNThlEsmuFiJbLBXio=

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=""
GOARCH="amd64"
GOBIN=""
GOCACHE="$HOME/Library/Caches/go-build"
GOENV="$HOME/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="$HOME/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="$HOME/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.15.6/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.15.6/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="$HOME/workspace/pls-gopls/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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/p8/_ykby0cs2x36vll5y_hrsr7c0000gn/T/go-build537755662=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Have been using gopls with emacs (via lsp-mode) and noticed that even with a brand new golang project using go modules, it was incredibly slow to get the LSP to recognize any new packages I'd create. There were multiple instances where I observed that it took minutes (~5-15) for the LSP to recognize that a new struct I'd made in a new package existed, albeit providing logs of the following form immediately on package creation:

2021/02/28 20:31:18 go/packages.Load
	snapshot=61
	package="jwal.dev/pls-gopls/two"
	files=[$HOME/workspace/pls-gopls/two/foo.go]

These appeared to indicate to me that gopls knew my packages existed, as well as their source files which contained my new structs I wanted to interact through the LSP with (e.g. completions). However, it reality they remained unknown until I saw logs of the form background refresh finished after Xs.

Digging into it more, it appears that this background refresh process scans either the entire gopath or the go module from its root then doesn't try again for 50 x (however long that took) seconds: https://github.com/golang/tools/blob/f5a4005dda57a682af872b31ea2ae6999aa44971/internal/lsp/cache/imports.go#L117

More often than not, I observed this taking only 1-3 seconds (which is still concerningly slow for a brand new go project with only two source code files) in turn meaning that the next refresh wouldn't happen for 1-2 minutes. There was a not insignificant number of times it took even longer, like say 10-20 seconds (not sure why) which in turn meant it wouldn't refresh again for another 10-15 minutes which is far too long.

I don't quite entirely understand the intention behind that frequency calculation; regardless though, it seems like something that should be configurable for those of us who are content to do that tuning ourselves. At the very least, we should decrease the frequency because it seems like a very unnecessarily large backoff.

What did you expect to see?

Background import refresh happening at a reasonable frequency on the order of seconds (< minute)

What did you see instead?

Background import refresh happening at an unreasonable frequency on the order of minutes

@gopherbot gopherbot added this to the Unreleased milestone Mar 1, 2021
@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Mar 1, 2021

It sounds likely that there is a different issue happening here, since gopls should not be slow on small projects, and the background refresh would not be causing this slowdown. Can you please share a gopls log by following these steps?

@jspawar
Copy link
Author

@jspawar jspawar commented Mar 3, 2021

@stamblerre Attaching my logs below, but would love if you could clarify why you don't believe the background imports cache refresh is the issue though please.

I have consistently seen that new packages appear to be not recognized by the LSP until the background imports refresh completes. I will close buffers, write files, etc., but not until the instant whenever the refresh process completes (I follow gopls logs up side-by-side) do I receive my newly-created package in say, my list of completions for using a variable in that package for instance (this example is the primary issue I'm having with it). I am uncertain of what triggers the actual refresh process to kick off in the first place, so I suspect perhaps your better knowledge of that is why you believe it is not causing an issue?

Also fwiw regarding the timings I observed of those background imports refreshing processes: it appears that it consistently takes a few seconds (~10-15) on its first run sometime after the server first starts up then each subsequent refresh takes around ~1-2 seconds. These are again, my observations from creating simple go modules projects from scratch and adding one or two new packages each with one new struct in them.

LSP logs
2021/03/02 16:52:50 go env for $HOME/workspace/gopls-wat-do
(root $HOME/workspace/gopls-wat-do)
(go version go version go1.15.6 darwin/amd64)
(valid build configuration = true)
(build flags: [])
GOPROXY=https://proxy.golang.org,direct
GOMODCACHE=$HOME/go/pkg/mod
GONOPROXY=
GONOSUMDB=
GO111MODULE=
GOFLAGS=
GOINSECURE=
GOMOD=$HOME/workspace/gopls-wat-do/go.mod
GOSUMDB=sum.golang.org
GOPRIVATE=
GOROOT=/usr/local/Cellar/go/1.15.6/libexec
GOCACHE=$HOME/Library/Caches/go-build
GOPATH=$HOME/go

2021/03/02 16:52:50 go/packages.Load
snapshot=0
directory=$HOME/workspace/gopls-wat-do
query=[builtin jwal.dev/gopls-wat-do/...]
packages=2

Creating watch for $HOME/workspace/gopls-wat-do
2021/03/02 16:53:20 background imports cache refresh starting

Creating watch for $HOME/workspace/gopls-wat-do/foo
2021/03/02 16:53:30 background refresh finished after 9.857008216s

Command "gopls" is present on the path.
Command "gopls" is present on the path.
Command "gopls" is present on the path.
Found the following clients for $HOME/workspace/gopls-wat-do/foo/structs.go: (server-id gopls, priority 0)
The following clients were selected based on priority: (server-id gopls, priority 0)
2021/03/02 16:53:33 go/packages.Load
snapshot=5
directory=$HOME/workspace/gopls-wat-do
query=[file=$HOME/workspace/gopls-wat-do/foo/structs.go]
packages=1

2021/03/02 16:53:33 go/packages.Load
snapshot=5
package="jwal.dev/gopls-wat-do/foo"
files=[$HOME/workspace/gopls-wat-do/foo/structs.go]

2021/03/02 16:53:33 go/packages.Load
snapshot=5
directory=$HOME/workspace/gopls-wat-do
query=[file=$HOME/workspace/gopls-wat-do/foo/structs.go]
packages=1

2021/03/02 16:53:33 go/packages.Load
snapshot=5
package="jwal.dev/gopls-wat-do/foo"
files=[$HOME/workspace/gopls-wat-do/foo/structs.go]

2021/03/02 16:53:35 go/packages.Load
snapshot=9
directory=$HOME/workspace/gopls-wat-do
query=[file=$HOME/workspace/gopls-wat-do/foo/structs.go]
packages=1

2021/03/02 16:53:35 go/packages.Load
snapshot=9
package="jwal.dev/gopls-wat-do/foo"
files=[$HOME/workspace/gopls-wat-do/foo/structs.go]

Cancelling textDocument/documentLink(82) in hook after-change-functions
Cancelling textDocument/codeAction(81) in hook after-change-functions
2021/03/02 16:53:37 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:4:2: expected ';', found 'EOF' (and 2 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:38 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:4:2: expected ';', found 'EOF' (and 2 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:38 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:3:7: expected type, found newline
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:38 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:4:2: expected ';', found 'EOF' (and 2 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:39 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:4:2: expected ';', found 'EOF' (and 2 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

Cancelling textDocument/codeAction(90) in hook after-change-functions
Cancelling textDocument/codeAction(91) in hook after-change-functions
2021/03/02 16:53:41 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:4:2: expected ';', found 'EOF' (and 2 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

Cancelling textDocument/codeAction(94) in hook after-change-functions
Cancelling textDocument/codeAction(98) in hook after-change-functions
2021/03/02 16:53:45 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:8:2: expected '(', found 'EOF' (and 4 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:45 no signature help: cannot find an enclosing function
position={6 6}

Cancelling textDocument/codeAction(101) in hook after-change-functions
2021/03/02 16:53:46 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:8: expected 'IDENT', found newline (and 4 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

Cancelling textDocument/codeAction(102) in hook after-change-functions
2021/03/02 16:53:46 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:10: expected 'IDENT', found newline (and 4 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

Cancelling textDocument/codeAction(103) in hook after-change-functions
2021/03/02 16:53:47 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:15: expected 'IDENT', found newline (and 4 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:47 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:16: expected 'IDENT', found newline (and 4 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:48 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:16: expected 'IDENT', found newline (and 4 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:49 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:21: expected '(', found newline (and 3 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:49 no completions found: this is a definition of func (Thing).Hello(invalid type)
position={6 20}

2021/03/02 16:53:49 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:7:21: expected '(', found newline (and 3 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:49 no completions found: this is a definition of func (Thing).Hello(invalid type)
position={6 20}

2021/03/02 16:53:49 no completions found: this is a definition of func (Thing).Hello(invalid type)
position={6 20}

2021/03/02 16:53:49 no signature help: cannot find an enclosing function
position={6 21}

Cancelling textDocument/codeAction(114) in hook after-change-functions
Cancelling textDocument/codeAction(120) in hook after-change-functions
2021/03/02 16:53:54 go/packages.Load
snapshot=100
package="jwal.dev/gopls-wat-do/foo"
files=[$HOME/workspace/gopls-wat-do/foo/structs.go]

2021/03/02 16:53:54 go/packages.Load
snapshot=100
directory=$HOME/workspace/gopls-wat-do
query=[file=$HOME/workspace/gopls-wat-do/foo/structs.go]
packages=1

2021/03/02 16:53:57 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:10:14: string literal not terminated (and 7 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:57 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:10:14: string literal not terminated (and 7 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:58 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:10:17: missing ',' in argument list (and 7 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:53:58 imports fixes: AllImportsFixes: $HOME/workspace/gopls-wat-do/foo/structs.go:10:17: missing ',' in argument list (and 7 more errors)
file="$HOME/workspace/gopls-wat-do/foo/structs.go"

2021/03/02 16:54:00 no signature help: cannot find an enclosing function
position={10 1}

2021/03/02 16:54:02 background imports cache refresh starting

2021/03/02 16:54:03 background refresh finished after 1.010874132s

Cancelling textDocument/documentLink(180) in hook post-command-hook
Cancelling textDocument/codeAction(179) in hook post-command-hook
Cancelling textDocument/codeAction(186) in hook after-change-functions
2021/03/02 16:54:33 background imports cache refresh starting

2021/03/02 16:54:34 background refresh finished after 984.486551ms

2021/03/02 16:54:41 go/packages.Load
snapshot=138
package="jwal.dev/gopls-wat-do"
files=[$HOME/workspace/gopls-wat-do/main.go]

2021/03/02 16:54:41 go/packages.Load
snapshot=138
directory=$HOME/workspace/gopls-wat-do
query=[file=$HOME/workspace/gopls-wat-do/main.go]
packages=1

Cancelling textDocument/codeAction(212) in hook after-change-functions
2021/03/02 16:55:09 background imports cache refresh starting

2021/03/02 16:55:10 background refresh finished after 979.343914ms

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Mar 3, 2021

I have consistently seen that new packages appear to be not recognized by the LSP until the background imports refresh completes. I will close buffers, write files, etc., but not until the instant whenever the refresh process completes (I follow gopls logs up side-by-side) do I receive my newly-created package in say, my list of completions for using a variable in that package for instance (this example is the primary issue I'm having with it). I am uncertain of what triggers the actual refresh process to kick off in the first place, so I suspect perhaps your better knowledge of that is why you believe it is not causing an issue?

The background imports refresh is only used by the import organization logic, and based on your first description, it seemed like the issue was with diagnostics:

LSP to recognize that a new struct I'd made in a new package existed

When you mention completion above, are you referring to completions for a package you have already imported into your program or a package that has not yet been imported? A repro case would be best here.

It also looks like those logs are not verbose--is there a way for you to add -rpc.trace as a flag when the gopls process is started? I'm not too familiar with lsp-mode so I'm sorry I can't advise on exactly how to do that. Also, it looks like you created a repro project, so if you'd be willing to share the code you're working with that would be easiest.

@jspawar
Copy link
Author

@jspawar jspawar commented Mar 8, 2021

Thank you for clarifying re: background imports refresh.

When you mention completion above, are you referring to completions for a package you have already imported into your program or a package that has not yet been imported? A repro case would be best here.

The latter: fails to provide completion for a package which was just created, but yet to be imported in the current file.

Repro that I've been doing looks something like this:

  1. go mod init a new project
  2. Create the most minimal main.go
  3. mkdir $PROJECT_ROOT/newpkg
  4. (Hopefully did the following heredoc correctly)
cat << EOF > $PROJECT_ROOT/newpkg/newtypes.go
package newpkg

type NewThing struct {}
EOF
  1. Open main.go in editor
  2. Start typing newpkg expecting to see newpkg show up as a package completion or newpkg.NewThing to show up as a possible completion (instead no completions related to the newpkg package are provided, at least until LSP server is manually restarted or some other unknown, slow event which I attributed to the background imports refresh originally)

It also looks like those logs are not verbose--is there a way for you to add -rpc.trace as a flag when the gopls process is started?

Not quite certain myself either haha, but I will try to figure it out and attach them here/a separate comment when I get the time. Just wanted to respond since it had been a few days and didn't want this going stale.

@jspawar
Copy link
Author

@jspawar jspawar commented Mar 8, 2021

Combating Sunday scaries a bit strangely here with this late debugging, but figured out how to increase the logging level with lsp-mode (if anyone else is curious: (setq lsp-go-gopls-server-args '("-rpc.trace")))

I noticed that doing my above repro actually worked as expected: my package was suggested as a completion almost immediately multiple times (not always, but maybe we can just gloss over those for now).

I decided to try and carry on with the project I was originally working in which I was creating a new package called client. Once I resumed that, I ran into the same issue where the package was no longer suggested as a completion, instead receiving completions for various other client packages from various go projects in my system's go cache.

Modified the original repo above to instead:

  1. mkdir $PROJECT_ROOT/client
  2. Create a new type in that package:
cat << EOF > client/my_client.go
package client

type MyClient struct {}
EOF
  1. Start typing client expecting to see completion for my package, instead saw completions for various client packages from other random projects in my system's go cache

I noticed in the logs (attached below) pretty much always saw a isIncomplete: true for textDocument/completion responses related to whenever I was typing out client hoping to get a completion for my project's client package. Seems like this is the culprit then?

In which case I'm wondering if it's intentional or not that gopls doesn't prioritize project packages for completion? Regardless, I guess I'd like to pivot then towards discussing (or opening a new issue to discuss) if it's reasonable to request of gopls to prioritize project packages for package completion?

Logs: https://gist.github.com/jspawar/538af493d62f8d9d8b659933c0799983

@stamblerre stamblerre added this to To Do in gopls: v1.0.0 Mar 11, 2021
@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Mar 11, 2021

I tried reproducing this and noticed that it would take a couple of seconds before the imports cache refreshed, at which point client.MyClient was the top result. @heschik will be able to weigh in on this, in case there are other issues here, but I think the imports logic does prioritize packages in the workspace. The amount of time it takes to refresh the cache may depend based on how large your module cache is. To confirm that it works as expected, you can reload the editor to force a gopls restart.

I noticed in the logs (attached below) pretty much always saw a isIncomplete: true for textDocument/completion responses related to whenever I was typing out client hoping to get a completion for my project's client package. Seems like this is the culprit then?

The isIncomplete setting is unrelated--it is set so that the editor client continues requesting completion results as you type more characters.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
3 participants