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: slow in overlay testdata/ packge #34360

Open
muirrn opened this issue Sep 17, 2019 · 7 comments

Comments

@muirrn
Copy link

commented Sep 17, 2019

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

$ go version
go version go1.12.9 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What did you do?

I created an overlay package (i.e. not saved on disk) in the tools repo, e.g. tools/internal/lsp/testdata/banana/banana.go with contents "package banana".

What did you expect to see?

I expected gopls to work with reasonable responsiveness.

What did you see instead?

Every change to the file triggered a very slow go/packages call. The changes would queue up, so if I typed 10 characters quickly, it would take 30 seconds before gopls caught up. It was hard to save the file because my organizeImports pre-save hook was getting stuck in the queue as well. Here is the log from one keypress:

2019/09/17 14:37:07 91.159572ms for GOROOT= GOPATH=/Users/muir/projects/<project>/go GO111MODULE= PWD=/Users/muir/projects/tools/ go "env" "GOMOD", stderr: <<>>

2019/09/17 14:37:07 99.643867ms for GOROOT= GOPATH=/Users/muir/projects/<project>/go GO111MODULE= PWD=/Users/muir/projects/tools/ go "list" "-m" "-json" "all", stderr: <<>>

2019/09/17 14:37:09 1.965799648s for GOROOT= GOPATH=/Users/muir/projects/<project>/go GO111MODULE= PWD=/Users/muir/projects/tools/ go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" "/Users/muir/projects/tools/internal/lsp/testdata/banana", stderr: <<go: finding golang.org/x/tools/internal/lsp/testdata/banana latest
go: finding golang.org/x/tools/internal/lsp/testdata latest
go: finding golang.org/x/tools/internal/lsp latest
go: finding golang.org/x/tools/internal latest
>>

2019/09/17 14:37:09 25.266872ms for GOROOT= GOPATH=/Users/muir/projects/<project>/go GO111MODULE= PWD=/Users/muir/projects/tools/ go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" "/Users/muir/projects/tools/internal/lsp/testdata/banana/banana.go", stderr: <<stat /Users/muir/projects/tools/internal/lsp/testdata/banana/banana.go: no such file or directory
>>

2019/09/17 14:37:10 541.27115ms for GOROOT= GOPATH=/Users/muir/projects/<project>/go GO111MODULE= PWD=/Users/muir/projects/tools/ go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "-mod=readonly" "--" "golang.org/x/tools/internal/memoize" "golang.org/x/tools/internal/telemetry/log" "reflect" "bytes" "golang.org/x/tools/internal/span" "go/scanner" "go/token" "golang.org/x/tools/internal/lsp/protocol" "golang.org/x/tools/internal/telemetry/trace" "go/parser" "golang.org/x/tools/internal/lsp/telemetry" "golang.org/x/tools/internal/lsp/source" "golang.org/x/xerrors" "go/ast" "context", stderr: <<>>
@gopherbot gopherbot added this to the Unreleased milestone Sep 17, 2019
@gopherbot

This comment has been minimized.

Copy link

commented Sep 17, 2019

Thank you for filing a gopls issue! Please take a look at the Troubleshooting section of the gopls Wiki page, and make sure that you have provided all of the relevant information here.

@tbhartman

This comment has been minimized.

Copy link

commented Sep 18, 2019

I am seeing similarly slow behavior during go list (takes 4-5 seconds per run) when using gopls in VSCode. In my case, I only see the slowdown when editing imports, but the changes are queued such that typing 5 characters leads to 5 times the delay (animation at 20x speed...full time of animation was 1.8 minutes)

20Um0

Log from gopls (not same as animation, but editing imports in a different file):

[Info  - 11:14:17 AM] 2019/09/18 11:14:17 345.9982ms for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" "builtin", stderr: <<>>
[Info  - 11:14:17 AM] 2019/09/18 11:14:17 628.9988ms for [redacted] go "list" "-m" "-json" "all", stderr: <<>>
[Info  - 11:14:18 AM] 2019/09/18 11:14:18 845.9969ms for [redacted] go "env" "GOMOD", stderr: <<>>
[Info  - 11:14:18 AM] 2019/09/18 11:14:18 319.9983ms for [redacted] go "env" "GOMOD", stderr: <<>>
[Info  - 11:14:19 AM] 2019/09/18 11:14:19 832.9994ms for [redacted] go "list" "-m" "-json" "all", stderr: <<>>
[Info  - 11:14:23 AM] 2019/09/18 11:14:23 5.0190297s for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" [redacted], stderr: <<>>
[Info  - 11:14:23 AM] 2019/09/18 11:14:23 go/packages.Load
[Info  - 11:14:23 AM] 2019/09/18 11:14:23 go/packages.Load
[Info  - 11:14:23 AM] 2019/09/18 11:14:23 go/packages.Load
[Info  - 11:14:24 AM] 2019/09/18 11:14:24 275.9977ms for [redacted] go "env" "GOMOD", stderr: <<>>
[Info  - 11:14:24 AM] 2019/09/18 11:14:24 520.0013ms for [redacted] go "list" "-m" "-json" "all", stderr: <<>>
[Info  - 11:14:29 AM] 2019/09/18 11:14:29 4.2761617s for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" [redacted], stderr: <<>>
[Info  - 11:14:29 AM] 2019/09/18 11:14:29 go/packages.Load
[Info  - 11:14:29 AM] 2019/09/18 11:14:29 go/packages.Load
[Info  - 11:14:29 AM] 2019/09/18 11:14:29 go/packages.Load
[Info  - 11:14:34 AM] 2019/09/18 11:14:34 280.9992ms for [redacted] go "list" "-m" "-json" "all", stderr: <<>>
[Info  - 11:14:34 AM] 2019/09/18 11:14:34 739.0044ms for [redacted] go "env" "GOMOD", stderr: <<>>
[Info  - 11:14:39 AM] 2019/09/18 11:14:39 4.6301423s for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" [redacted], stderr: <<>>
[Info  - 11:14:39 AM] 2019/09/18 11:14:39 292.9698ms for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "-mod=readonly" "--" "fm", stderr: <<>>
[Info  - 11:14:39 AM] 2019/09/18 11:14:39 go/packages.Load
[Info  - 11:14:39 AM] 2019/09/18 11:14:39 go/packages.Load
[Info  - 11:14:39 AM] 2019/09/18 11:14:39 go/packages.Load
[Info  - 11:14:39 AM] 2019/09/18 11:14:39 503.0017ms for [redacted] go "list" "-m" "-json" "all", stderr: <<>>
[Info  - 11:14:40 AM] 2019/09/18 11:14:40 726.0504ms for [redacted] go "env" "GOMOD", stderr: <<>>
[Info  - 11:14:43 AM] 2019/09/18 11:14:43 4.0372971s for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" [redacted], stderr: <<>>
[Info  - 11:14:43 AM] 2019/09/18 11:14:43 265.0874ms for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "-mod=readonly" "--" "fm", stderr: <<>>
[Info  - 11:14:43 AM] 2019/09/18 11:14:43 go/packages.Load
[Info  - 11:14:43 AM] 2019/09/18 11:14:43 go/packages.Load
[Info  - 11:14:43 AM] 2019/09/18 11:14:43 go/packages.Load
[Info  - 11:14:44 AM] 2019/09/18 11:14:44 272.0332ms for [redacted] go "env" "GOMOD", stderr: <<>>
[Info  - 11:14:44 AM] 2019/09/18 11:14:44 718.0346ms for [redacted] go "list" "-m" "-json" "all", stderr: <<>>
[Info  - 11:14:48 AM] 2019/09/18 11:14:48 4.2415797s for [redacted] go "list" "-e" "-json" "-compiled=true" "-test=true" "-export=false" "-deps=true" "-find=false" "--" [redacted], stderr: <<>>
[Info  - 11:14:48 AM] 2019/09/18 11:14:48 go/packages.Load
[Info  - 11:14:48 AM] 2019/09/18 11:14:48 go/packages.Load
[Info  - 11:14:48 AM] 2019/09/18 11:14:48 go/packages.Load
@stamblerre

This comment has been minimized.

Copy link
Contributor

commented Sep 18, 2019

@muirrn: By change to the file, do you mean change in the file's imports? That's the only time go/packages should be called.

@tbhartman: What version of gopls are you using? Make sure it's the latest by running go get golang.org/x/tools/gopls@latest. There are some issues with manual imports taking a bit to catch up, but it should never be more than a second. If you are seeing this with v0.1.7, then please open a separate issue, and I will help you debug there. It doesn't seem like your code is necessarily in an overlay.

@muirrn

This comment has been minimized.

Copy link
Author

commented Sep 18, 2019

By change to the file, do you mean change in the file's imports?

No, it was happening after any change until I saved the file. I assume the go/packages call is failing so it keeps retrying after every change.

@stamblerre

This comment has been minimized.

Copy link
Contributor

commented Sep 18, 2019

Do overlays behave like this if you use them in other directories? Is it possibly something specific that's strange about the internal/lsp/testdata directory?

@muirrn

This comment has been minimized.

Copy link
Author

commented Sep 19, 2019

I tried it in a non-testdata directory and it is certainly different. It doesn't get stuck, but no LSP features work and I get LSP :: stat /Users/muir/projects/tools/internal/lsp/banana/banana.go: no such file or directory every time I change or do anything (probably a separate issue from testdata).

@muirrn muirrn changed the title x/tools/gopls: slow go/packages call after every change in overlay package x/tools/gopls: slow in overlay testdata/ packge Oct 9, 2019
@muirrn

This comment has been minimized.

Copy link
Author

commented Oct 9, 2019

Do we care about gopls in testdata/ packages? Is it an accident that it works at all, or should it be supported?

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