cmd/compile: slow compilation of a package with a very large API

[baywet]

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

go1.18.2 windows/amd64

the OS doesn't seem to be making a big difference, and I was experiencing the issue since at least go 17

Does this issue reproduce with the latest release?

yes

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

set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\vibiret\AppData\Local\go-build
set GOENV=C:\Users\vibiret\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\vibiret\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\vibiret\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.18.2
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\sources\gitlocal\gorepro\go.mod
set GOWORK=
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=C:\Users\vibiret\AppData\Local\Temp\go-build1532428258=/tmp/go-build -gno-record-gcc-switches

What did you do?

go mod init main
go get github.com/microsoftgraph/msgraph-sdk-go@v0.24.1 #takes about 20 seconds on my machine, expected, this is the large package we're maintaining
go get github.com/Azure/azure-sdk-for-go/sdk/azidentity@v1.0.0 # takes about 5 seconds, expected
go get github.com/microsoft/kiota-authentication-azure-go@v0.3.0 # takes about 2 seconds, expected

notepad main.go #or code, vim,... whatever you have on your OS

# paste the content from the appendix

go build # takes about 1m30s, long but expected

Now replace the following lines

-result, err := client.Me().Messages().Get()
+result, err := client.Me().MailFoldersById("Inbox").Messages().Get()

Then run go build again, which takes about 30 seconds, not expected, should take a couple of seconds thanks to caching.

What did you expect to see?

Subsequent builds should be in the sub seconds time as the packages should be cached.

What did you see instead?

Takes about the original build time.

Additional context

We're maintaining a large package that's generated from an API description. The API itself is fairly large. The initial ask from our SDK users was about the build time increasing significantly when adding our package and caching seeming like it's not fully working from one go build to another.

With the release of 1.18 and generics, we're already identified opportunities for improvements to generate less code, but haven't acted on it yet. @breml @josharian @dominikh were really helpful with framing the issue and suggested we posted here before making those improvements.

Additionally, the go doc for our package is not working either.

Appendix

main.go content

package main

import (
	"context"
	"fmt"

	azidentity "github.com/Azure/azure-sdk-for-go/sdk/azidentity"
	a "github.com/microsoft/kiota-authentication-azure-go"
	r "github.com/microsoft/kiota-http-go"
	msgraphsdk "github.com/microsoftgraph/msgraph-sdk-go"
)

func main() {
	cred, err := azidentity.NewDeviceCodeCredential(&azidentity.DeviceCodeCredentialOptions{
		TenantID: "placeholder",
		ClientID: "placeholder",
		UserPrompt: func(ctx context.Context, message azidentity.DeviceCodeMessage) error {
			fmt.Println(message.Message)
			return nil
		},
	})
	if err != nil {
		fmt.Printf("Error creating credentials: %v\n", err)
	}
	auth, err := a.NewAzureIdentityAuthenticationProviderWithScopes(cred, []string{"Mail.Read", "Mail.Send"})
	if err != nil {
		fmt.Printf("Error authentication provider: %v\n", err)
		return
	}
	adapter, err := r.NewNetHttpRequestAdapter(auth)
	if err != nil {
		fmt.Printf("Error creating adapter: %v\n", err)
		return
	}
	client := msgraphsdk.NewGraphServiceClient(adapter)
	result, err := client.Me().Messages().Get()
	if err != nil {
		fmt.Printf("Error executing request: %v\n", err)
		return
	}
	if result != nil {
		fmt.Printf("Got a result")
		return
	}
}

[mvdan]

should take a couple of seconds thanks to caching.

To add some context for people coming across this issue: Go's build cache works at the package level, so modifying a package in any way will generally mean rebuilding the entire package. See https://pkg.go.dev/cmd/go#hdr-Build_and_test_caching.

[baywet]

Adding @randall77 @griesemer @matloob @rsc @bcmills @golang/pkgsite for visibility here. Sorry about the spam, but we're trying to get traction.

[mvdan]

Please don't do that. The majority of the people you pinged don't even work on the compiler regularly.

[baywet]

Apologies. This is not something I usually do. What's the right process?

[bcmills]

A good starting point might be to make the issue more actionable by tracing the command to figure out where the bottleneck is.
@matloob added an experimental -debug-trace flag in CL 237683 — could you try running the unexpectedly slow command with -debug-trace=<some file>, and then view it with go tool trace to see where it is spending its time?

That would at least help identify the appropriate maintainers to route this issue to, or perhaps even an opportunity for you to contribute a fix.

[baywet]

Thanks for the guidance
Here is what I did:

1. go build -debug-trace="initial.out"
2. edit the code with a trivial change
3. go build -debug-trace="final.out"
4. go tool trace final.out

Which results in

2022/07/12 10:30:59 Parsing trace...
failed to parse trace: not a trace file

Attaching the files.
traces.zip

[bcmills]

Looks like the trace can be opened by the viewer hosted at https://ui.perfetto.dev/.

[baywet]

Thanks.
From what I can see, there are three aspects that take a while:

• load.PackagesAndErrors
• build dependencies
• link

It looks to me that we could save approx half the time if the former was running on multiple thread instead of single threaded. I don't know much about the internals though, is there a specific reason why that's running on a single thread at the moment?

For build dependencies, most of the steps "take no time" which I'm assuming means they are being retrieved from cache. However some do take a little bit of time although they haven't changed, could it indicate a cache miss?

For the later, could/should the link result be cached to some extent?

[bcmills]

The threading behavior in the trace doesn't match the actual threading behavior of the program — it's kind of an impedance mismatch between Go's threading model and the model expected by the trace viewer. However, the indexing changes coming up in Go 1.19 are intended to speed up that loading phase, especially on platforms with unusually slow filesystems (such as Windows 😅).

For build dependencies, most of the steps "take no time" which I'm assuming means they are being retrieved from cache. However some do take a little bit of time although they haven't changed, could it indicate a cache miss?

Possibly, yes. And we do expect to see at least one cache miss for package main. 🤔

For the [latter], could/should the link result be cached to some extent?

Unfortunately, linking a Go program is not incremental: if any of the inputs changes, the entire link step must be redone. It might be worth profiling and/or tracing the linker to see what can be done to reduce the latency of that step, but I know a lot of work has already gone into making the linker faster.

For now, the best way to speed up linking is to present the linker with less code: that is, to break up APIs into smaller packages so that the linker doesn't have to process (and discard) a lot of irrelevant code.

[baywet]

Go 1.19 speeding up loading

Great, looking forward to that version! Are you looking for feedback on those aspects? (i.e. would you like me to run the trace with go 1.19 and see if we get different results?)

cache miss

Any action I should take to investigate that further?

no linking cache

Understood, thanks for the context. Is that work going to be part of Go1.19 as well?

reduce the code

We already identified a couple of actions we'll take or the API users can take to reduce the packages sizes. I was encouraged by the community using our SDK to reach out here before they are implemented because even if our code-base is large, some of the behaviour that was observed seemed odd.

[baywet]

Another aspect we didn't get into so far is the documentation for the models sub package is failing to display https://pkg.go.dev/github.com/microsoftgraph/msgraph-sdk-go@v0.28.0/models