search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
123.58k stars 17.61k forks source link

x/tools/gopls: textDocument/implementation is slow #58653

Closed hyangah closed 1 year ago

hyangah commented 1 year ago

gopls version

gopls built @ 3ec30bd95cd143796a8b51514c85d5667d261333

go version -m ~/go/bin/gopls ``` go version -m ~/go/bin/gopls /Users/hakim/go/bin/gopls: go1.20.1 path golang.org/x/tools/gopls mod golang.org/x/tools/gopls (devel) dep github.com/BurntSushi/toml v1.2.1 h1:9F2/+DoOYIOksmaJFPw1tGFy1eDnIJXg+UHjuD8lTak= dep github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= dep github.com/sergi/go-diff v1.1.0 h1:we8PVUC3FE2uYfodKH/nBHMSetSfHDR6scGdBi+erh0= dep golang.org/x/exp v0.0.0-20220722155223-a9213eeb770e h1:+WEEuIdZHnUeJJmEUjyYC2gfUMj69yZXw17EnHg/otA= dep golang.org/x/exp/typeparams v0.0.0-20221212164502-fae10dda9338 h1:2O2DON6y3XMJiQRAS1UWU+54aec2uopH3x7MAiqGW6Y= dep golang.org/x/mod v0.8.0 h1:LUYupSeNrTNCGzR/hVBk2NHZO4hXcVaW1k4Qx7rjPx8= dep golang.org/x/sync v0.1.0 h1:wsuoTGHzEhffawBOhz5CYhcrV4IdKZbEyZjBMuTp12o= dep golang.org/x/sys v0.5.0 h1:MUK/U/4lj1t1oPg0HfuXDN/Z1wv31ZJ/YcPiGccS4DU= dep golang.org/x/text v0.7.0 h1:4BRB4x83lYWy72KwLD/qYDuTu7q9PjSagHvijDw7cLo= dep golang.org/x/tools (devel) dep golang.org/x/vuln v0.0.0-20230110180137-6ad3e3d07815 h1:A9kONVi4+AnuOr1dopsibH6hLi1Huy54cbeJxnq4vmU= dep honnef.co/go/tools v0.3.3 h1:oDx7VAwstgpYpb3wv0oxiZlxY+foCpRAwY7Vk6XpAgA= dep mvdan.cc/gofumpt v0.4.0 h1:JVf4NN1mIpHogBj7ABpgOyZc65/UUOkKQFkoURsz4MM= dep mvdan.cc/xurls/v2 v2.4.0 h1:tzxjVAj+wSBmDcF6zBB7/myTy3gX9xvi8Tyr28AuQgc= build vcs.revision=3ec30bd95cd143796a8b51514c85d5667d261333 build vcs.time=2023-02-22T21:51:18Z ```

go env

go1.20.1 darwin/amd64

What did you do?

git clone https://github.com/juju/juju cd juju

And open vscode from the directory. Open utils/stringforwarder/stringforwarder.go Hover over StringForwarder type def (line13), right click, choose "Find All Implementations"

This triggers textDocument/implementation LSP request

What did you expect to see?

Fast response or failure.

What did you see instead?

gopls becomes unresponsive for 10+min. Unfortunately, I couldn't find VS Code UI that causes cancellation of the implementation request. (so this isn't cancellable currently).

While the gopls server is blocked handling this request, none of the other requests can be served.

Once the first implementation response returns (after 10min+), gopls responds fast. But if I restart gopls, I see the initial loading time is much shorter, but the implementation query still takes several minutes and blocks other gopls functionalities.

Another strange behavior is the log messages about go command failures related to module download. I thought gopls would do module download when starting and warm the module cache. So the "module lookup disabled by GOPROXY=off" errors message is rather surprising and I wonder whether gopls managed to diagnose go.mod.

Editor and settings

VS Code

    "ui.completion.completionBudget": "1s",
    "build.directoryFilters": [
        "-**/node_modules"
    ],
    "ui.semanticTokens": true,
    "ui.documentation.linksInHover": false,
    "ui.codelenses": {
        "run_govulncheck": true
    },
    "ui.documentation.linkTarget": "foo.bar",
    "ui.inlayhint.hints": {
        "assignVariableTypes": true,
        "compositeLiteralFields": false,
        "compositeLiteralTypes": false,
        "constantValues": true,
        "functionTypeParameters": false,
        "parameterNames": false,
        "rangeVariableTypes": false
    },
    "ui.vulncheck": "Off",
    "allExperiments": true

Logs

...
[Trace - 11:30:44 PM] Received response 'textDocument/documentSymbol - (11)' in 37058ms.
Result: [...]

[Trace - 11:30:44 PM] Received response 'textDocument/codeAction - (12)' in 36574ms. Request failed: JSON RPC cancelled (-32800).
[Trace - 11:30:44 PM] Received response 'textDocument/codeAction - (13)' in 36584ms. Request failed: JSON RPC cancelled (-32800).
[Trace - 11:30:44 PM] Received response 'textDocument/semanticTokens/range - (14)' in 36380ms.
Result: {...}
....

[Trace - 11:30:44 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go","version":1,"diagnostics":[]}

[Trace - 11:31:14 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2023/02/22 23:31:14 background imports cache refresh starting\n"}

[Trace - 11:31:35 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2023/02/22 23:31:35 background refresh finished after 21.52114096s\n"}

[Trace - 11:31:39 PM] Sending request 'textDocument/hover - (20)'.
Params: {"textDocument":{"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go"},"position":{"line":12,"character":11}}

[Trace - 11:31:39 PM] Received response 'textDocument/hover - (20)' in 77ms.
Result: {"contents":{"kind":"markdown","value":"```go\ntype StringForwarder struct {\n\tmu           sync.Mutex\n\tcond         *sync.Cond\n\tcurrent      *string\n\tstopped      bool\n\tdiscardCount uint64\n}\n\nfunc (*StringForwarder).Forward(msg string)\nfunc (*StringForwarder).Stop() uint64\nfunc (*StringForwarder).invokeCallback(callback func(string), msg string)\nfunc (*StringForwarder).loop(callback func(string))\n```\n\nStringForwarder is a goroutine-safe type that pipes messages from the its Forward() method, sending them to callback.  The send will not be blocked by the callback, but will instead discard messages if there is an incomplete callback in progress. The number of discarded messages is tracked and returned when the forwarder is stopped.\n"},"range":{"start":{"line":12,"character":5},"end":{"line":12,"character":20}}}

...

[Trace - 11:31:47 PM] Sending request 'textDocument/implementation - (23)'.
Params: {"textDocument":{"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go"},"position":{"line":12,"character":11}}

[Trace - 11:32:23 PM] Sending request 'textDocument/hover - (24)'.
Params: {"textDocument":{"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go"},"position":{"line":23,"character":5}}

[Trace - 11:32:25 PM] Sending notification '$/cancelRequest'.
Params: {"id":24}
....
[Trace - 11:33:04 PM] Sending notification '$/cancelRequest'.
Params: {"id":26}

[Trace - 11:33:26 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2023/02/22 23:33:26 tidy: diagnosing file:///Users/hakim/projects/juju/go.mod: err: exit status 1: stderr: go: downloading github.com/jessevdk/go-flags v1.5.0\ngo: downloading github.com/vishvananda/netlink v1.2.1-beta.2\ngo: downloading github.com/canonical/go-dqlite v1.11.5\ngo: downloading github.com/pkg/term v1.1.0\ngo: downloading github.com/juju/qthttptest v0.1.3\ngo: downloading github.com/rogpeppe/clock v0.0.0-20190514195947-2896927a307a\ngo: downloading github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1\ngo: downloading github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute v1.0.0\ngo: downloading github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/internal v1.0.0\ngo: downloading github.com/testcontainers/testcontainers-go v0.11.1\ngo: downloading github.com/onsi/ginkgo v1.14.0\ngo: downloading github.com/onsi/gomega v1.10.1\ngithub.com/juju/juju/core/network imports\n\tgithub.com/vishvananda/netlink: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/database/app imports\n\tgithub.com/canonical/go-dqlite/app: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/database/app imports\n\tgithub.com/canonical/go-dqlite/client: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/database/driver imports\n\tgithub.com/canonical/go-dqlite/driver: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju imports\n\tgithub.com/canonical/pebble/cmd/pebble imports\n\tgithub.com/jessevdk/go-flags: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju imports\n\tgithub.com/canonical/pebble/cmd/pebble imports\n\tgithub.com/canonical/pebble/internal/ptyutil imports\n\tgithub.com/pkg/term/termios: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/api imports\n\tgithub.com/go-macaroon-bakery/macaroon-bakery/v3/httpbakery tested by\n\tgithub.com/go-macaroon-bakery/macaroon-bakery/v3/httpbakery.test imports\n\tgithub.com/juju/qthttptest: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/api imports\n\tgopkg.in/retry.v1 tested by\n\tgopkg.in/retry.v1.test imports\n\tgithub.com/rogpeppe/clock/testclock: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/cmd/juju/commands imports\n\tgithub.com/chzyer/readline tested by\n\tgithub.com/chzyer/readline.test imports\n\tgithub.com/chzyer/test: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/provider/azure imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2 tested by\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2.test imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/provider/azure imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2 tested by\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2.test imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/internal/testutil: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/secrets/provider/vault imports\n\tgithub.com/mittwald/vaultgo tested by\n\tgithub.com/mittwald/vaultgo.test imports\n\tgithub.com/mittwald/vaultgo/test/testdata imports\n\tgithub.com/testcontainers/testcontainers-go: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/secrets/provider/vault imports\n\tgithub.com/mittwald/vaultgo tested by\n\tgithub.com/mittwald/vaultgo.test imports\n\tgithub.com/mittwald/vaultgo/test/testdata imports\n\tgithub.com/testcontainers/testcontainers-go/wait: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/ginkgo: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/ginkgo/config: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/ginkgo/types: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/gomega: module lookup disabled by GOPROXY=off\n\n"}

[Trace - 11:33:26 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///Users/hakim/projects/juju/container/lxd/export_test.go","diagnostics":[{"range":{"start":{"line":50,"character":46},"end":{"line":50,"character":57}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://foo.bar/golang.org/x/tools/internal/typesinternal#UndeclaredName"},"source":"compiler","message":"undefined: SnapManager"},{"range":{"start":{"line":51,"character":21},"end":{"line":51,"character":35}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://foo.bar/golang.org/x/tools/internal/typesinternal#UndeclaredName"},"source":"compiler","message":"undefined: getSnapManager"},{"range":{"start":{"line":51,"character":44},"end":{"line":51,"character":55}},"severity":1,"code":"UndeclaredName","codeDescription":{"href":"https://foo.bar/golang.org/x/tools/internal/typesinternal#UndeclaredName"},"source":"compiler","message":"undefined: SnapManager"}]}

[Trace - 11:33:27 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2023/02/22 23:33:27 tidy: diagnosing file:///Users/hakim/projects/juju/go.mod: err: exit status 1: stderr: go: downloading github.com/vishvananda/netlink v1.2.1-beta.2\ngo: downloading github.com/jessevdk/go-flags v1.5.0\ngo: downloading github.com/canonical/go-dqlite v1.11.5\ngo: downloading github.com/pkg/term v1.1.0\ngo: downloading github.com/juju/qthttptest v0.1.3\ngo: downloading github.com/rogpeppe/clock v0.0.0-20190514195947-2896927a307a\ngo: downloading github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1\ngo: downloading github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute v1.0.0\ngo: downloading github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/internal v1.0.0\ngo: downloading github.com/testcontainers/testcontainers-go v0.11.1\ngo: downloading github.com/onsi/ginkgo v1.14.0\ngo: downloading github.com/onsi/gomega v1.10.1\ngithub.com/juju/juju/core/network imports\n\tgithub.com/vishvananda/netlink: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/database/app imports\n\tgithub.com/canonical/go-dqlite/app: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/database/app imports\n\tgithub.com/canonical/go-dqlite/client: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/database/driver imports\n\tgithub.com/canonical/go-dqlite/driver: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju imports\n\tgithub.com/canonical/pebble/cmd/pebble imports\n\tgithub.com/jessevdk/go-flags: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju imports\n\tgithub.com/canonical/pebble/cmd/pebble imports\n\tgithub.com/canonical/pebble/internal/ptyutil imports\n\tgithub.com/pkg/term/termios: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/api imports\n\tgithub.com/go-macaroon-bakery/macaroon-bakery/v3/httpbakery tested by\n\tgithub.com/go-macaroon-bakery/macaroon-bakery/v3/httpbakery.test imports\n\tgithub.com/juju/qthttptest: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/api imports\n\tgopkg.in/retry.v1 tested by\n\tgopkg.in/retry.v1.test imports\n\tgithub.com/rogpeppe/clock/testclock: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/cmd/juju/commands imports\n\tgithub.com/chzyer/readline tested by\n\tgithub.com/chzyer/readline.test imports\n\tgithub.com/chzyer/test: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/provider/azure imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2 tested by\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2.test imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/provider/azure imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2 tested by\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute/v2.test imports\n\tgithub.com/Azure/azure-sdk-for-go/sdk/resourcemanager/internal/testutil: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/secrets/provider/vault imports\n\tgithub.com/mittwald/vaultgo tested by\n\tgithub.com/mittwald/vaultgo.test imports\n\tgithub.com/mittwald/vaultgo/test/testdata imports\n\tgithub.com/testcontainers/testcontainers-go: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/secrets/provider/vault imports\n\tgithub.com/mittwald/vaultgo tested by\n\tgithub.com/mittwald/vaultgo.test imports\n\tgithub.com/mittwald/vaultgo/test/testdata imports\n\tgithub.com/testcontainers/testcontainers-go/wait: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/ginkgo: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/ginkgo/config: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/ginkgo/types: module lookup disabled by GOPROXY=off\ngithub.com/juju/juju/caas/kubernetes/provider/mocks imports\n\tk8s.io/client-go/applyconfigurations/admissionregistration/v1 imports\n\tk8s.io/apimachinery/pkg/util/managedfields imports\n\tk8s.io/kube-openapi/pkg/util/proto tested by\n\tk8s.io/kube-openapi/pkg/util/proto.test imports\n\tgithub.com/onsi/gomega: module lookup disabled by GOPROXY=off\n\n"}

[Trace - 11:34:12 PM] Sending request 'textDocument/codeAction - (27)'.
Params: {"textDocument":{"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go"},"range":{"start":{"line":27,"character":17},"end":{"line":27,"character":17}},"context":{"diagnostics":[],"triggerKind":2}}

[Trace - 11:34:12 PM] Sending request 'textDocument/hover - (28)'.
Params: {"textDocument":{"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go"},"position":{"line":27,"character":16}}

[Trace - 11:34:13 PM] Sending notification '$/cancelRequest'.
Params: {"id":28}

...

[Trace - 11:45:45 PM] Sending request 'textDocument/hover - (32)'.
Params: {"textDocument":{"uri":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go"},"position":{"line":30,"character":29}}

[Trace - 11:45:46 PM] Sending notification '$/cancelRequest'.
Params: {"id":32}

[Trace - 11:48:25 PM] Received response 'textDocument/implementation - (23)' in 997596ms.
No result returned.

[Trace - 11:48:25 PM] Received response 'textDocument/hover - (24)' in 962122ms. Request failed: JSON RPC cancelled (-32800).
[Trace - 11:48:25 PM] Received response 'textDocument/hover - (25)' in 923091ms. Request failed: JSON RPC cancelled (-32800).
[Trace - 11:48:25 PM] Received response 'textDocument/hover - (26)' in 922806ms. Request failed: JSON RPC cancelled (-32800).
[Trace - 11:48:25 PM] Received response 'textDocument/codeAction - (27)' in 853586ms.
Result: [{"title":"Fill StringForwarder","kind":"refactor.rewrite","edit":{},"command":{"title":"Fill StringForwarder","command":"gopls.apply_fix","arguments":[{"Fix":"fill_struct","URI":"file:///Users/hakim/projects/juju/utils/stringforwarder/stringforwarder.go","Range":{"start":{"line":27,"character":10},"end":{"line":27,"character":40}}}]}}]
hyangah commented 1 year ago

I don't see slowness of textDocument/implementation nor the error log related to the tidy diagnostics with gopls v0.11.0. Another observation is, the range of memory usage is wider; I observed 1G ~ 8G with gopls@master, 2G ~4G with gopls@v0.11.0.

findleyr commented 1 year ago

CC @adonovan

adonovan commented 1 year ago

The juju test case above can be reduced to this command:

$ time gopls implementation utils/stringforwarder/stringforwarder.go:#492

I observed these timings with different versions of gopls over three sequential runs:

So it was definitely very slow during the period when it used the new implementation algorithm but before it actually saved the file-based index, yet it has since gotten better and is now at least at parity with v0.11.0, so this is no longer a release blocker.

But there is still room for improvement.

findleyr commented 1 year ago

Thanks for the investigation. Moving this to the v0.13.0 milestone as I think implementation is fast enough, and we have bigger fish to fry.

findleyr commented 1 year ago

Given that we've improved so much from the initial report, let's not keep this open. Any subsequent improvement should be motivated by new information.