x/tools/imports: pathological behaviour when package result is in same module

[myitcv]

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

$ go version
go version devel +44c9354c5a Fri Jun 21 05:21:30 2019 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20190620191750-1fa568393b23
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.0.0-20190620191750-1fa568393b23

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN="/home/myitcv/gostuff/src/github.com/myitcv/govim/cmd/govim/.bin"
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/gostuff/src/github.com/myitcv/govim/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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build649018026=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Per discussion with @heschik on Slack.

The other case is where I know a qualified identifier refers to a package in the current module, imports still heads off to scan the module cache

It might make sense to kick off the two queries concurrently, i.e. current module and module cache, but the latter will take a long time to come back with ~5G of code

But I would expect the latter query to be cancelled when the former returns a match, which will be very fast.

On a machine with a large amount of code in $GOPATH/pkg/mod, the following script will roughly show the slow performance. I think this is representative of the general case; other specific examples which are harder to reproduce exactly, exhibit even worse behaviour but are, I think, the same class of problem.

# install goimports
env GOPROXY=https://proxy.golang.org
go install golang.org/x/tools/cmd/goimports

# test goimports
env GOPROXY=$GOMODPROXY
cd mod

# run goimports
exec goimports -w main.go

# check result
cmp main.go main.go.golden

-- go.mod --
module goimports

require golang.org/x/tools v0.0.0-20190620191750-1fa568393b23

-- mod/go.mod --
module mod.com

-- mod/main.go --
package main

func main() {
	p.Println("")
}
-- mod/main.go.golden --
package main

import "mod.com/p"

func main() {
	p.Println("")
}
-- mod/p/p.go --
package p

func Println(s string) {}

On my machine (~5GB of code in the module cache), I see the following:

$ testscript -v -e GOPATH goimports_same_module_package.txt

...

# install goimports (0.091s)
> env GOPROXY=https://proxy.golang.org
> go install golang.org/x/tools/cmd/goimports
# test goimports (0.000s)
> env GOPROXY=$GOMODPROXY
> cd mod
$WORK/mod
# run goimports (0.959s)
> exec goimports -w main.go
# check result (0.000s)
> cmp main.go main.go.golden
PASS

What did you expect to see?

goimports taking next to no time at all, because there is a "match" within the current module.

I think imports needs prioritise its search according to module distance from the main module, falling back to the module cache as a last resort.

Furthermore, I don't think the query against the module cache should be kicked off until modules reachable from the main module (including standard library of course) have been evaluated. Reason being, with a large amount of code in the module cache, the processing and IO cost can be huge.

What did you see instead?

goimports taking a long time, ~10 seconds for some particularly bad cases. In gopls, if you are invoking imports via "format-on-save", which is a blocking operation, this is particularly painful.

cc for FYI @stamblerre @ianthehat