x/tools/gopls: code action to organize imports blocking

[myitcv]

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

$ go version
go version devel +aacbd7c3aa Thu Sep 24 09:15:20 2020 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20201009162240-fcf82128ed91
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.0.0-20201009162240-fcf82128ed91

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/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/myitcv/gostuff/pkg/mod"
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/.vim/plugged/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-build112124304=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I don't have a specific repro per se, just noting per a conversation on #gopls-dev an apparent change in behaviour.

The crux of the issue is that a code action call to organize imports takes "a long time" where before it did not. In govim we trigger this as part of a blocking pre-save routine, hence a change in this behaviour is easily noticeable.

"Long time" might be anything up to 20 seconds, but more commonly is around 3 seconds. Whilst not long in the context of the history of the universe, in the context of a blocking UI call it feels like an age 😄

This appears to be most easily triggered by refactoring code in, say, a test file, where a reference t to a *testing.T is moved out of scope of the declaration of t, thereby triggering the organize imports code to try and resolve a package for the qualified identifier t.

Notes on what I've observed so far:

• this appears to be made worse by larger projects, i.e. with larger dependency sets
• this problem is particularly bad after a machine restart
• closing Vim (and govim) and re-opening causes a longer delay (3 secs) compared to re-saving post an initial save (200ms) despite the fact I am using a remote LSP setup where the remote instance is not destroyed after the last client closes

What did you expect to see?

(Based on my understanding of how things should work following the last major "refactor")

No increased execution time of the organize imports code action call. It should return an answer based on the currently available cached package data.

Periodically, the goimports cache should be refreshed async from any LSP client calls.

What did you see instead?

Per above

cc @muirdm based on the report from Slack where you also saw this behaviour.

---

cc @stamblerre

FYI @leitzler

[stamblerre]

/cc @heschik

[heschi]

Please include a log.

[myitcv]

@heschik I haven't managed to pin down the circumstances that lead to the worst case performance, but this is a run after a machine boot:

gopls.log

Notice the call took ~17s.

My recollection/expectation (based on previous discussions about this) is that this call should never be blocking on a refresh of the goimports cache. Rather it should use the current state of the cache, and that cache should be refreshed periodically.

[heschi]

Sorry, I don't understand. There are no completion requests in that log; what took 17s?

[myitcv]

There are no completion requests in that log

We're not talking about completion here, rather a code action call:

[Trace - 08:48:32.191 AM] Sending request 'textDocument/codeAction - (2)'.
Params: {"textDocument":{"uri":"file:///home/myitcv/dev/learn.go.dev/gitea/cmd/gitea/main_test.go"},"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"context":{"diagnostics":null}}


[Trace - 08:48:49.498 AM] Received response 'textDocument/codeAction - (2)' in 17306ms.

[heschi]

Oh, right, sorry. Churning through email too quickly.

What you're saying about not blocking is only for autocomplete. It doesn't apply to imports on save, which is essentially a call to the goimports command line. Unlike autocomplete, imports on save is not a best effort call; it takes as long as it takes to get an answer. If the cache is cold, because you haven't done any autocompletes yet or whatever, then it may indeed be quite slow. 17 seconds seems unreasonable but 3 is in line with what we see from Macs.

I suspect you will see the exact same behavior with the goimports command line after a reboot. You can pass -v and show a log if you like, but most likely this is just going to boil down to Macs being bad at filesystems as usual.

[myitcv]

What you're saying about not blocking is only for autocomplete

Interesting. This must be a combination of my misremembering and an unfortunate (pathological) refactor which triggered this wide search.

17 seconds seems unreasonable but 3 is in line with what we see from Macs

This is on Linux FWIW.

Thanks for the response. I'll close this as working as intended, unless you think there's mileage in making imports on save best efforts?

[heschi]

I think that's explicitly not what users want; if you hit save you expect your imports to show up, not for it to silently give up after a second or two. Obviously faster would be better.

If it's Linux on an SSD this is somewhat more surprising. I would be curious to see a goimports -v run, but it's unlikely there's going to be much to do. A single-character "import" is a pathological worst case for goimports since it has to fully parse every package with that letter in the name looking for exports.