x/tools/gopls: >45s for first completion of unimported package

[leitzler]

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

$ go version
go version go1.13.5 darwin/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20191219041853-979b82bfef62
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.8-0.20191219041853-979b82bfef62

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/pontus/Library/Caches/go-build"
GOENV="/Users/pontus/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/pontus/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/pontus/proj/govim/latest_tools/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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/xm/ls208xd174v95pgd20rn_qbh0000gn/T/go-build213935326=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Open up a new module

$ cd $(mktemp -d) && go mod init x && vi main.go

Then type in:

package main

func main() {
        fmt.|
}

And at | trigger a completion request.

What did you expect to see?

Completion request return a little bit faster.

What did you see instead?

The response arrives after ~47 seconds. See https://gist.github.com/leitzler/29eca825af07416bae63c1c304527994#file-gopls-log-L429

As per discussion on Slack with @heschik it looks like it is due to package name loading.

Rerun with verboseOutput:

2019/12/19 21:43:19 gopathwalk: scanning /Users/pontus/go/pkg/mod
2019/12/19 21:43:19 Directory added to ignore list: /Users/pontus/go/pkg/mod/cache
2019/12/19 21:43:23 gopathwalk: scanned /Users/pontus/go/pkg/mod in 3.864949127s
[Trace - 21:44:04.398 PM] Received response 'textDocument/completion - (2)' in 44771ms.

Mod cache size:

$ time find $(go env GOPATH)/pkg/mod/ -type d | wc -l
   79000
real	0m10.360s
user	0m0.519s
sys	0m6.519s

[leitzler]

@gopherbot please remove label Documentation

[heschi]

I'm going to hijack this for a braindump of performance problems with unimported completions.

• With a large enough GOPATH/module cache, a scan can be prohibitively expensive. We cannot block a user action on a scan finishing.

  • This implies either cancelling the scan after the completion budget expires, or detaching it to run asynchronously.
  • It also makes dumping the whole cache and rescanning it from scratch a bad idea. We need to update incrementally or do the rescan in the background (https://golang.org/cl/212022).
  • Ideally we would do the scan in relevancy order so that we can give the most useful completions as fast as possible. In module mode, at least, we can prime the cache based on the go list -m results, then do the full scan later. In GOPATH mode I don't think there's much to be done since the only signal is imported packages and we should have those anyway, see below.
  • We set a limit on the number of unimported completions returned. Once we have that satisfied, we should immediately unblock the user.

• In GOPATH mode, anything can change at any time. We have to trade off between latency, or at least resource consumption, and correctness.

  • A mitigating factor is that we prefer to use real type-check results when available, which means we'll have correct data for stuff already in workspace scope no matter what. Small bug here: the outer loop is only over the things found in the scan, so if there's a candidate known to gopls but not in the scan we'll miss it.

• In module mode, we can assume that module cache entries don't change. All we need to do is add new things, and maybe delete everything if the user runs clean -modcache.

• Since GOPATH and the module cache can change so differently, there isn't a single brute-force strategy that works for both. Ideally we can update the cache incrementally, which is a good strategy in both cases.

  • Incremental updates are also good for user experience; we can give them the best results we have and continue re-scanning in the background.

• No matter the strategy, scans chew up CPU time/power/disk bandwidth. I don't want to add knobs, but I also don't want to be doing 47 seconds of work every 30 seconds...

• At least in this report, loading package names was the most expensive part of the process by far. We could load names on demand based on a heuristic match of the filesystem path, as goimports does today.

@stamblerre @muirmanders @ianthehat

[heschi]

Notes to self as of https://golang.org/cl/212634:

• Missed a major trick in the discussion above, which is simply to stop doing work when it looks like we have enough results to overwhelm the user. That's done.
• Scan cancellation is almost done. gopathwalk cancellation is impossible without redesigning fastwalk to be postorder, but we can detach them easily enough.
  • It might make sense to process the cache first to see if that yields enough results, and only then do the walks. But then we need to know what's new, vs. rescanning the whole cache.
• The API now exists to do goimports-style directory filtering, just have to implement it.

[heschi]

Submitted a bunch of stuff. Most everything from the above is done. Remaining:

• Detachable walks. In this report, it took 4 seconds to do the filesystem walk. We shouldn't hang the request that long.
• Reattachable walks. Following the above, it would be spiffy to reattach to a walk in progress, rather than blocking for it to finish.
• Incremental rescans. I'm on the fence about this. With lazy package loading, it might be sufficient to do the walk in the background (see https://golang.org/cl/212022) and then let the user pull in more stuff.

[heschi]

Since I keep getting distracted, one more update: https://golang.org/cl/212022 is the last thing I intend to do here. Other than that we should be in good shape.

[heschi]

This should be fixed, or at least fixed enough to be on by default.