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 golang/tools@f79f3aa. (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