x/tools/gopls: textDocument/definition is slow in large codebase

[aashishkapur]

gopls version

golang.org/x/tools/gopls v0.9.4
    golang.org/x/tools/gopls@v0.9.4 h1:YhHOxVi++ILnY+QnH9FGtRKZZrunSaR7OW8/dCp7bBk=
    github.com/BurntSushi/toml@v1.2.0 h1:Rt8g24XnyGTyglgET/PRUNlrUeu9F5L+7FilkXfZgs0=
    github.com/google/go-cmp@v0.5.8 h1:e6P7q2lk1O+qJJb4BtCQXlK8vWEO8V1ZeuEdJNOqZyg=
    github.com/sergi/go-diff@v1.1.0 h1:we8PVUC3FE2uYfodKH/nBHMSetSfHDR6scGdBi+erh0=
    golang.org/x/exp/typeparams@v0.0.0-20220722155223-a9213eeb770e h1:7Xs2YCOpMlNqSQSmrrnhlzBXIE/bpMecZplbLePTJvE=
    golang.org/x/mod@v0.6.0-dev.0.20220419223038-86c51ed26bb4 h1:6zppjxzCulZykYSLyVDYbneBfbaBIQPYMevg0bEwv2s=
    golang.org/x/sync@v0.0.0-20220722155255-886fb9371eb4 h1:uVc8UZUe6tr40fFVnUP5Oj+veunVezqYl9z7DYw9xzw=
    golang.org/x/sys@v0.0.0-20220722155257-8c9f86f7a55f h1:v4INt8xihDGvnrfjMDVXGxw9wrfxYyCjk0KbXjhR55s=
    golang.org/x/text@v0.3.7 h1:olpwvP2KacW1ZWvsR7uQhoyTYvKAupfQrRGBFM352Gk=
    golang.org/x/tools@v0.1.13-0.20220812184215-3f9b119300de h1:b68wxF4nfQjj1XTRHtjVjCximbhAwjztuzDEFGU+n9o=
    honnef.co/go/tools@v0.3.2 h1:ytYb4rOqyp1TSa2EPvNVwtPQJctSELKaMyLfqNP4+34=
    mvdan.cc/gofumpt@v0.3.1 h1:avhhrOmv0IuvQVK7fvwV91oFSGAk5/6Po8GXTzICeu8=
    mvdan.cc/xurls/v2@v2.4.0 h1:tzxjVAj+wSBmDcF6zBB7/myTy3gX9xvi8Tyr28AuQgc=
go: go1.17.6

go env

GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ubuntu/.cache/go-build"
GOENV="/home/ubuntu/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS="-mod=readonly"
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/ubuntu/co/backend/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/ubuntu/co/backend/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/ubuntu/co/backend/opt/go1.17.6"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/ubuntu/co/backend/opt/go1.17.6/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.6"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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-build457205370=/tmp/go-build -gno-record-gcc-switches"

What Happened

I noticed that go-to-definition in vscode on a go file was taking a long time, and consistently saw the following log when navigating within a package (specifically, I was using go to definition to navigate within a package. I'm operating within a large monorepo, with some heavily interlinked packages)

[Trace - 23:17:36.892 PM] Received response 'textDocument/definition - (213)' in 11214ms.

I pulled up the "Trace Information" tab in the debug server, and found a log for textDocument/Definition RPC. This log looks to consist of cache.parseGo and cache.TypeCheck events, but many of these events are replicated, seemly indicating that duplicate work is build done. I see multiple packages being parsed many times (up to ~20, looks to be dependent on imports), with all of its files listed underneath

0s textDocument/definition 13.862321388s start="textDocument/definition" method="textDocument/definition" direction="in" id="#20"

    13.862319081s label= status.code="OK" 

    74.474µs queued 27.786µs start="queued"
    178.05µs source.Identifier 13.861909568s start="source.Identifier"
...
3.12062168s cache.typeCheck 192.827411ms start="cache.typeCheck" package="foo [bar.test]" 
    3.120790449s cache.parseGo 196.421µs start="cache.parseGo" file="foo/file_a.go" 
    .... <package files> ...
...
3.590160298s cache.typeCheck 317.260966ms start="cache.typeCheck" package="foo [baz.test]" 
    3.590357772s cache.parseGo 274.427µs start="cache.parseGo" file="foo/file_a.go" 
    .... <package files> ...
...
5.043508487s cache.typeCheck 175.931042ms start="cache.typeCheck" package="foo [foo2.test]" 
    5.492814972s cache.parseGo 351.925µs start="cache.parseGo" file="foo/file_a.go" 
    .... <package files> ...
...

Appears that there's duplicate work being done - I looked through the codebase for these events and found many todos added in https://github.com/golang/tools/commit/f79f3aac190554ef62f0257555394b31c29f0320. (eg a b). Is there any planned work to speed up the cache.typeCheck and cache.parseGo operations?

Happy to DM the full trace file to someone if that would help!

[findleyr]

Thanks for the investigation! The full trace file would be helpful, as would RPC logs from your session: https://github.com/golang/vscode-go/blob/master/docs/troubleshooting.md#collect-gopls-information

I don't think you should ever see duplicate results in the span of a single definition request. If you're seeing this, it indicates a rather severe bug / race. Any additional information you could provide would be greatly appreciated.

[findleyr]

After looking at this a bit more, it is possible that due to some of the memory optimizations gopls has in place we may encounter that cache.typeCheck entry up to three times a single package up to three times (though the majority of packages should be type checked only once).

However, more concerning is the duplicate "cache.parseGo" spans for a single within the same definition trace. If I'm understanding correctly, this is what you are reporting as happening up to 20 times.

[findleyr]

So, the only way that cache.typeCheck spans would be in your definition trace is if the forward transitive closure of the current file was not actually type-checked. That's surprising to me: for example, I was not able to reproduce during even by immediately issuing a definition request in Kubernetes.

Are you able to reproduce this reliably? If so, does it reproduce on every definition request, or just the first?

[aashishkapur]

(files removed, happy to share if needed) ~aashishkapur - gopls trace info.txt~ ~gopls rpcs.txt~

Here's the full trace information - as an example, the samsaradev.io/gqlschema package is referenced 23 times. This portion of the codebase has a pretty messy import graph, so requests only take this long in these specific packages. Other portions of the codebase don't have these issues. This seems to indicate that these requests may be influenced by the import graph of this package.

The request originates from samsaradev.io/gqlschema/gqldvirs/gqldvirs.go - I do see some of the cache.TypeCheck events for the gqldvirs package appearing to use the cache(because of no associated cache.parseGo logs). However, I don't see this use of the cache for any other packages.

Are you able to reproduce this reliably? If so, does it reproduce on every definition request, or just the first?

I am able to repo this reliably, and this occurs on every request from this package.

Thanks for taking a look!

[aashishkapur]

Could you also clarify the intended behavior here? After the initial rpc is made (textDocument/definition), should we be relying on the gopls cache, or does the lsp cache always have some parsing to do to complete the request?

[aashishkapur]

if the forward transitive closure of the current file was not actually type-checked

I do see a bunch of these logs in the gopls output - I wonder if some packages aren't getting type checked correctly, causing gopls to reindex packages every time this occurs.

[Trace - 06:21:26.633 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2022/09/22 06:21:26 discovered missing identifiers: map[thirdPartyDeviceCreationForAssetTemplateArgs:true]\n\tpackage=\"samsaradev.io/industrial/gqlindustrial [samsaradev.io/models/accessors/driversaccessor.test]\"\n"}

I'm not sure exactly what this means though - if you think this is relevant, could you help decode this log? I do notice that the second argument is always a .test package

[aashishkapur]

@findleyr - mind taking a look at https://go-review.googlesource.com/c/tools/+/433335 ?

Turns out the logs are relevant - they were indicating that gopls was re-parsing certain packages while responding to these RPCs. I did some more digging and found that the private types mentioned in the logs were exposed publicly through type casting. e.g. The presence of

type parser struct {
    ...
}
type ParseOption func(p *parser)

was forcing recomputation of a package, as the parser type wasn't cached.

After commenting out the relevant types, I found that gopls resolved RPCs in a timely manner. I believe that this caused a huge impact for me because of how messed up the import graph is for these packages - we have two packages with code like the above, and the combination looks like it could cause up to tens of package recomputations!

Here are some public packages which were also mentioned in logs:

discovered missing identifiers: map[acquireLockOptions:true createDynamoDBTableOptions:true releaseLockOptions:true sendHeartbeatOptions:true]\n\tpackage=\"cirello.io/dynamolock
discovered missing identifiers: map[bracketPair:true options:true]\n\tpackage=\"golang.org/x/text/unicode/bidi
discovered missing identifiers: map[bracketPair:true]\n\tpackage=\"vendor/golang.org/x/text/unicode/bidi
discovered missing identifiers: map[cardinality:true kind:true syntax:true value:true]\n\tpackage=\"google.golang.org/protobuf/reflect/protoreflect
discovered missing identifiers: map[clientCreator:true eventDispatcher:true]\n\tpackage=\"github.com/palantir/go-githubapp/githubapp
discovered missing identifiers: map[clockTimer:true]\n\tpackage=\"github.com/benbjohnson/clock
discovered missing identifiers: map[config:true]\n\tpackage=\"github.com/NYTimes/gziphandler
discovered missing identifiers: map[config:true]\n\tpackage=\"github.com/lightstep/lightstep-tracer-go/internal/metrics
discovered missing identifiers: map[connCtx:true]\n\tpackage=\"github.com/alicebob/miniredis
discovered missing identifiers: map[cors:true]\n\tpackage=\"github.com/gorilla/handlers
discovered missing identifiers: map[countMetric:true gaugeMetric:true setMetric:true]\n\tpackage=\"github.com/DataDog/datadog-go/statsd
discovered missing identifiers: map[counter:true]\n\tpackage=\"go.uber.org/zap/zapcore
discovered missing identifiers: map[cpuMask:true]\n\tpackage=\"golang.org/x/sys/unix
discovered missing identifiers: map[crossChunkImportItem:true]\n\tpackage=\"github.com/evanw/esbuild/internal/bundler
discovered missing identifiers: map[defaultKey:true endpointKey:true region:true service:true]\n\tpackage=\"github.com/aws/aws-sdk-go/aws/endpoints
discovered missing identifiers: map[describedType:true]\n\tpackage=\"github.com/Azure/go-amqp
discovered missing identifiers: map[differ:true]\n\tpackage=\"github.com/wI2L/jsondiff
discovered missing identifiers: map[digestEntry:true]\n\tpackage=\"github.com/docker/distribution/digestset
discovered missing identifiers: map[edge:true]\n\tpackage=\"github.com/armon/go-radix
discovered missing identifiers: map[encOpts:true encodeState:true]\n\tpackage=\"github.com/globalsign/mgo/internal/json
discovered missing identifiers: map[encodeState:true]\n\tpackage=\"gopkg.in/square/go-jose.v2/json
discovered missing identifiers: map[eventListenerMapEntry:true]\n\tpackage=\"gopkg.in/DataDog/dd-trace-go.v1/internal/appsec/dyngo
discovered missing identifiers: map[eventLog:true]\n\tpackage=\"golang.org/x/net/trace
discovered missing identifiers: map[extensionsByNumber:true]\n\tpackage=\"google.golang.org/protobuf/reflect/protoregistry
discovered missing identifiers: map[fetchPageResult:true]\n\tpackage=\"cloud.google.com/go/bigquery
discovered missing identifiers: map[fieldKey:true]\n\tpackage=\"github.com/sirupsen/logrus
discovered missing identifiers: map[formatter:true]\n\tpackage=\"gonum.org/v1/gonum/mat
discovered missing identifiers: map[inode:true]\n\tpackage=\"github.com/boltdb/bolt
discovered missing identifiers: map[layer:true]\n\tpackage=\"github.com/getsentry/sentry-go
discovered missing identifiers: map[matcher:true]\n\tpackage=\"golang.org/x/text/language
discovered missing identifiers: map[message:true]\n\tpackage=\"github.com/google/pprof/profile
discovered missing identifiers: map[messageDataType:true unknownFieldsA:true]\n\tpackage=\"google.golang.org/protobuf/internal/impl
discovered missing identifiers: map[options:true]\n\tpackage=\"github.com/grpc-ecosystem/go-grpc-middleware/recovery
discovered missing identifiers: map[parser:true]\n\tpackage=\"golang.org/x/net/html
discovered missing identifiers: map[peekIterator:true]\n\tpackage=\"github.com/Azure/azure-service-bus-go
discovered missing identifiers: map[pinEvent:true reactionEvent:true sendConfig:true starEvent:true]\n\tpackage=\"github.com/slack-go/slack
discovered missing identifiers: map[point:true]\n\tpackage=\"gonum.org/v1/plot/tools/bezier
discovered missing identifiers: map[queryQueueEntry:true]\n\tpackage=\"github.com/golang/geo-fork/s2
discovered missing identifiers: map[recordOptions:true]\n\tpackage=\"go.opencensus.io/stats
discovered missing identifiers: map[stop:true]\n\tpackage=\"github.com/fogleman/gg
discovered missing identifiers: map[term:true]\n\tpackage=\"golang.org/x/tools/internal/typeparams
discovered missing identifiers: map[token:true]\n\tpackage=\"github.com/google/licenseclassifier/stringclassifier/searchset/tokenizer
discovered missing identifiers: map[tokenStream:true]\n\tpackage=\"github.com/Knetic/govaluate
discovered missing identifiers: map[userSearch:true]\n\tpackage=\"github.com/andygrunwald/go-jira
discovered missing identifiers: map[yaml_emitter_t:true yaml_parser_t:true]\n\tpackage=\"github.com/zclconf/go-cty-yaml

I dug through most of these and believe that my change will fix these errors!

[findleyr]

@aashishkapur nice investigation! I will look at your CL (sorry for the delay: yesterday was awash with meetings).

Before I dig in, this is still surprising to me. A bit of background: gopls has a concept of a "workspace" package (a package that you are working on) vs a "non-workspace" package (a package that you import). Unfortunately, right now they go through most of the same code-paths, and we save a lot of information for non-workspace packages that is not necessary in most cases. In order to reduce this memory, we trim the AST of non-workspace packages before type-checking, so that we have the same package APIs, just for a smaller amount of code.

Resolving a definition request should be simple: make sure the current package is type-checked, and then figure out which go/types.Object is referenced at the cursor location, and jump to its Pos().

Subsequently, the editor may open a non-workspace package, turning it into a workspace package, but that should happen after the didOpen notification from the editor, not during the definition request. So once your workspace is loaded, a definition request should involve type-checking at most one package: the package containing the cursor. In the common case, however, this package will have already been type-checked during the diagnostics pass.

So while your CL may fix the problem, the fact that it fixes the problem is surprising to me, and may point to a different bug.

CC @adonovan

[aashishkapur]

oh, interesting. To clarify, does gopls trim a workspace package at all? How does gopls think about imports or dependencies of a package currently open in vscode?

I ask because I am navigating within the same package and see this re-parsing behavior. The trace info linked above is a request going from one file to another in the same package. I believe this is also present when navigating from one package to another, but I'll check.

[findleyr]

oh, interesting. To clarify, does gopls trim a workspace package at all? How does gopls think about imports or dependencies of a package currently open in vscode?

No, gopls does not trim a workspace package. It defines the workspace based on the go.mod or go.work boundaries of the open folder (i.e. expands to the nearest surrounding go.work or (failing that) go.mod). So if an import of an open package is within the same module (or a module referenced by go.work), then it will not be trimmed. If an import is outside that boundary, it will be trimmed.

There is definitely something broken about the behavior you are observing.

[aashishkapur]

I see - all packages with in a workspace should already be parsed.

All of these files / packages in this codebase are in a single workpace, with go.work:

go 1.17

use ./go/src/samsaradev.io

Would we expect the discovered missing identifiers message to appear when parsing a non-trimmed workspace?

[aashishkapur]

Another thought - i wonder if test packages are the cause of this re-parsing. The logs indicate that all re-parsing contains a test package Are _test packages treated differently by trimming? Could they be causing this behavior if the package isn't parsed completely?

[findleyr]

Ok, I think I understand what is happening.

@aashishkapur you are using a go.work file with Go 1.17. go.work was added in Go 1.18, but unfortunately gopls sort-of works around this, and probably in buggy ways (we're about to remove this functionality in #55331).

Are you able to try upgrading to Go 1.18 or later?

[aashishkapur]

Unfortunately, I'm still seeing the same issue

golang.org/x/tools/gopls v0.9.4
    golang.org/x/tools/gopls@v0.9.4 h1:YhHOxVi++ILnY+QnH9FGtRKZZrunSaR7OW8/dCp7bBk=
    github.com/BurntSushi/toml@v1.2.0 h1:Rt8g24XnyGTyglgET/PRUNlrUeu9F5L+7FilkXfZgs0=
    github.com/google/go-cmp@v0.5.8 h1:e6P7q2lk1O+qJJb4BtCQXlK8vWEO8V1ZeuEdJNOqZyg=
    github.com/sergi/go-diff@v1.1.0 h1:we8PVUC3FE2uYfodKH/nBHMSetSfHDR6scGdBi+erh0=
    golang.org/x/exp/typeparams@v0.0.0-20220722155223-a9213eeb770e h1:7Xs2YCOpMlNqSQSmrrnhlzBXIE/bpMecZplbLePTJvE=
    golang.org/x/mod@v0.6.0-dev.0.20220419223038-86c51ed26bb4 h1:6zppjxzCulZykYSLyVDYbneBfbaBIQPYMevg0bEwv2s=
    golang.org/x/sync@v0.0.0-20220722155255-886fb9371eb4 h1:uVc8UZUe6tr40fFVnUP5Oj+veunVezqYl9z7DYw9xzw=
    golang.org/x/sys@v0.0.0-20220722155257-8c9f86f7a55f h1:v4INt8xihDGvnrfjMDVXGxw9wrfxYyCjk0KbXjhR55s=
    golang.org/x/text@v0.3.7 h1:olpwvP2KacW1ZWvsR7uQhoyTYvKAupfQrRGBFM352Gk=
    golang.org/x/tools@v0.1.13-0.20220812184215-3f9b119300de h1:b68wxF4nfQjj1XTRHtjVjCximbhAwjztuzDEFGU+n9o=
    golang.org/x/vuln@v0.0.0-20220725105440-4151a5aca1df h1:BkeW9/QJhcigekDUPS9N9bIb0v7gPKKmLYeczVAqr2s=
    honnef.co/go/tools@v0.3.2 h1:ytYb4rOqyp1TSa2EPvNVwtPQJctSELKaMyLfqNP4+34=
    mvdan.cc/gofumpt@v0.3.1 h1:avhhrOmv0IuvQVK7fvwV91oFSGAk5/6Po8GXTzICeu8=
    mvdan.cc/xurls/v2@v2.4.0 h1:tzxjVAj+wSBmDcF6zBB7/myTy3gX9xvi8Tyr28AuQgc=
go: go1.18.4

I see the same re-parsing in the trace logs as well as the discovered missing identifiers messages. Fwiw, actions do appear snappier, but they're still taking some time to complete (5s on go1.18 vs 10s on go1.17 for the same action between the same two files)

[aashishkapur]

Here's some more trace info from running on go1.18, but for source.Identifer: ~gopls-trace.txt~ (files removed, happy to share if needed) I was navigating between two files in the same package, and see that the discovered missing identifiers for some test packages correspond to re-parsing of the source package(samsaradev.io/industrial/gqlindustrial), over and over again

This package contains code very similar to

type foo struct {} 
type x []foo 
type Exported struct{
    X x
}

which was a test case in my CL!

[findleyr]

Thanks again for the details!

I notice that all of the packages in your example are test variants, which seems highly likely to be related.

[findleyr]

Looking into this further, I believe this is a consequence of (or at least related to) https://go-review.git.corp.google.com/c/tools/+/347563, which intended to fix #47825.

In that CL we updated gopls to search test variants for the package containing the target position, to fix a problem that the target declaration was not found. This could potentially cause a lot of unnecessary synchronous type-checking if the target declaration is outside of the workspace. Even before that CL we were doing unnecessary type-checking, as there's no need for us to fully type-check the target package: we know which position we're jumping to.

In general, our textDocument/definition is doing way more work that it needs to, and I'm going to rewrite it to be much simpler, which on first principles should solve the problem you observe: we should only need the current package, which will already be type-checked.

However, I haven't yet reproduced behavior as poor as you observe, and I'm concerned that other logic (such as hover) that goes through the leaky source.Identifier abstraction will suffer the same problem. For example, from your trace I see that there are also slow textDocument/hover handlers.

[gopherbot]

Change https://go.dev/cl/438495 mentions this issue: gopls/internal/lsp/source: don't type-check in FindPackageFromPos

[gopherbot]

Change https://go.dev/cl/438496 mentions this issue: gopls/internal/lsp/source: use PackageFromFile in Identifier

[gopherbot]

Change https://go.dev/cl/438497 mentions this issue: gopls/internal/lsp/cache: make IsIntermediateTestVariant a method

[findleyr]

@aashishkapur I think the changes above should fix the problem, but could you test?

To install gopls at tip, you can do the following:

git clone https://go.googlesource.com/tools
cd tools/gopls
go install

[findleyr]

Gentle ping: anyone who experienced this issue, could you please confirm that it is now resolved?

Closing for now as I believe the root cause is understood and mitigated.

[aashishkapur]

@findleyr Thanks for your help here - performance is looking much much better!