x/tools/go/packages: Unusably slow when there are packages using cgo in the list

[segevfiner]

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

$ go version
go version go1.11.4 windows/amd64

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
set GOARCH=amd64
set GOBIN=
set GOCACHE=<snip>\AppData\Local\go-build
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=<snip>\go
set GOPROXY=
set GORACE=
set GOROOT=C:\Go
set GOTMPDIR=
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=<snip>\Temp\go-build664130090=/tmp/go-build -gno-record-gcc-switches

What did you do?

I tried using a Go tool that uses golang.org/x/go/tools/packages under the hood (Specifically gogetdoc, but many more tools are going to use it in order to support Go modules). Since packages unconditionally calls go list -compiled (go/tools/go/packages/golist.go:630), when there are large cgo modules anywhere on the module list, packages will cause them to be compiled, without any caching. This can take a very long time and makes any tool doing so unusably slow.

Steps to reproduce

You need to have ImageMagick available. (See https://github.com/gographics/imagick)

1. Save the following as main.go in a new go package directory:

package main

import "gopkg.in/gographics/imagick.v2/imagick"

func main() {
	imagick.Initialize()
}

2. dep init/go get/whatever.
3. gogetdoc -pos main.go:#87.

What did you expect to see?

The tool works fast.

What did you see instead?

It's extremely slow, to the point of being unusable.

Related issues

zmb3/gogetdoc#47
microsoft/vscode-go#667
microsoft/vscode-go#1025
rogpeppe/godef#103

cc @zmb3 @ramya-rao-a

[ALTree]

cc @matloob

[heschi]

#29371 is relevant. Does this reproduce at tip with that bug fixed? There's probably still a discussion to be had, but I imagine it'd be less urgent if it didn't happen every time.

[heschi]

Actually, never mind; that issue was specific to -find which wasn't in use until my https://golang.org/cl/155477 last week, and the related issues are much older.
@jayconrod

[heschi]

I'm not sure if this is because of cgo, or if it's just more noticeable because it takes so long to build cgo packages. I investigated by doing some go lists on a clean cache.

$ go clean -cache -modcache
$ go list -e -json -compiled -deps=true -- . | grep Stale
	"Stale": true,
	"StaleReason": "build ID mismatch",
	"Stale": true,
	"StaleReason": "stale dependency: gopkg.in/gographics/imagick.v2/imagick/types",
	"Stale": true,
	"StaleReason": "stale dependency: gopkg.in/gographics/imagick.v2/imagick/types",
$ go list -e -json -compiled -deps=true -- . | grep Stale          
	"Stale": true,
	"StaleReason": "build ID mismatch",
	"Stale": true,
	"StaleReason": "stale dependency: gopkg.in/gographics/imagick.v2/imagick/types",
	"Stale": true,
	"StaleReason": "stale dependency: gopkg.in/gographics/imagick.v2/imagick/types",
$ go build .
$ go list -e -json -compiled -deps=true -- . | grep Stale
	"Stale": true,
	"StaleReason": "not installed but available in build cache",
	"Stale": true,
	"StaleReason": "not installed but available in build cache",
	"Stale": true,
	"StaleReason": "not installed but available in build cache",

I would have expected the second command to reuse cached results from the first, but it doesn't. Doing a build manually puts things in the cache and the last list is fast. Seems like a bug to me.

[klauspost]

This is quite bad. Loading SSA for a package takes more than 1.5 hours. See referenced issue above.

[heschi]

I don't know what's going on in @klauspost's bug but it's not this one.

[jayconrod]

Some analysis:

• gogetdoc invokes packages.Load in AllSyntax mode, which asks for all available information on the package and its dependencies. Maybe this tool could ask for less. Looks like it wants type information, but maybe it could just get syntax trees?
• packages invokes go list -json -compiled -test=false -export=false -deps=true -- $PWD. As @segevfiner points out in the original report, -compiled is unconditional. Ideally, this would not be necessary for all modes, but it sounds like the current contract requires it.
• Because -compiled and -deps=true are passed, go list needs cgo results from every package in the dependency graph. cgo is very expensive for imagemagick. I'm not sure if it's doing a huge amount of work or if there's some optimization opportunity there.
• For packages that were cached from a previous run of go build, go list will re-use cached cgo files. Since b7451e2 (two weeks ago, not in 1.11), go list will also re-use cached cgo files from previous runs of go list (though go build won't re-use those files because of the way cache keys are derived).

I think this largely has the same root cause as #29371, so maybe this should be closed. However, I think it would be interesting to discuss whether go/packages could be invoked in a way that doesn't require cgo. cc @matloob

[matloob]

I'm working on a change (https://go-review.googlesource.com/c/tools/+/162140) that will allow tool to specify that they don't need the CompiledGoFiles field. Once that change is in, if a tool doesn't request CompiledGoFiles, or other Package struct fields that need compiled files, go/packages will invoke go list without -compiled.

[gopherbot]

Change https://golang.org/cl/162140 mentions this issue: go/packages: split LoadMode into fine-grained options

[jayconrod]

cc @matloob: is there anything else to do for this issue? It sounds like after https://golang.org/cl/162140, cgo is not always needed, but when it is needed, it still takes a long time.

[StevenACoffman]

As an example, a small project that is using cgo (via sqlc) running:

time go list -m -u all

resulted in:

real	11m17.749s
user	0m21.221s
sys	0m22.311s

But for some reason this is speedy:

time go list -m -f '{{if not (or .Indirect .Main)}}go get -u {{.Path}}@latest{{end}}' all

and results in:

real	0m0.243s
user	0m0.448s
sys	0m0.285s