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: code action to organize imports blocking #41969

Closed
myitcv opened this issue Oct 14, 2020 · 12 comments
Closed

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

myitcv opened this issue Oct 14, 2020 · 12 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. Tools This label describes issues relating to any tools in the x/tools repository. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@myitcv
Copy link
Member

myitcv commented Oct 14, 2020

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

@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 Oct 14, 2020
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Oct 14, 2020
@gopherbot gopherbot added this to the Unreleased milestone Oct 14, 2020
@stamblerre
Copy link
Contributor

/cc @heschik

@stamblerre stamblerre modified the milestones: Unreleased, gopls/v1.0.0 Oct 14, 2020
@heschi
Copy link
Contributor

heschi commented Oct 14, 2020

Please include a log.

@heschi heschi added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 14, 2020
@myitcv
Copy link
Member Author

myitcv commented Oct 15, 2020

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

heschi commented Oct 15, 2020

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

@myitcv
Copy link
Member Author

myitcv commented Oct 15, 2020

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

heschi commented Oct 15, 2020

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

myitcv commented Oct 15, 2020

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

heschi commented Oct 15, 2020

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.

@muirdm
Copy link

muirdm commented Oct 15, 2020

Anecdotally, before gopls I don't remember having slow goimports in my project. With gopls it often takes seconds when I save. (Note that my save hook does imports and formatting, and I'm not 100% sure it is imports). There are other vectors of slowness such as gopls computing other code actions beyond just imports, or perhaps gopls deciding it needs to run a "go list" or what not before it gets into the imports code.

@heschi
Copy link
Contributor

heschi commented Oct 15, 2020

I agree that there are many possible causes but in this case Paul has privately shared a goimports run that is exactly as slow as gopls, so here it's just the nonspecific search over a large module cache. I don't think there's anything in particular to do, unfortunately. Perhaps refuse to search for single-letter imports, but I'm sure that would annoy someone.

@stamblerre
Copy link
Contributor

@heschik: Is this OK to close?

@heschi
Copy link
Contributor

heschi commented Oct 29, 2020

Unless we're prepared to compromise on something, I don't have any ideas to improve the situation. So yeah.

@heschi heschi closed this as completed Oct 29, 2020
@stamblerre stamblerre removed this from the gopls/vscode-go milestone Oct 30, 2020
@golang golang locked and limited conversation to collaborators Oct 30, 2021
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. Tools This label describes issues relating to any tools in the x/tools repository. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

5 participants