cmd/compile: long build time (45 seconds) for a small package (1500 source lines of code)

[thomaspeugeot]

Go version

go version go1.21.5 darwin/amd64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/Users/thomaspeugeot/Library/Caches/go-build'
GOENV='/Users/thomaspeugeot/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/thomaspeugeot/go/pkg/mod'
GONOPROXY='github.com/thomaspeugeot,github.com/fullstack-lang'
GONOSUMDB='github.com/thomaspeugeot,github.com/fullstack-lang'
GOOS='darwin'
GOPATH='/Users/thomaspeugeot/go'
GOPRIVATE='github.com/thomaspeugeot,github.com/fullstack-lang'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.21.5'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/thomaspeugeot/go/src/github.com/thomaspeugeot/thelongbuild/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/_r/bxjvdzc17mb6p56qc7nms1r80000gn/T/go-build65103854=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

below are the steps to reproduce the timing result

on macos

rm -rf thelongbuild
git clone https://github.com/thomaspeugeot/thelongbuild.git
cd thelongbuild/go/tree
go clean -cache
time go build -v
sed -i '' 's/gongtree_buttons/gongtree_buttons_new/g' tree.go
time go build -v
cd ../../..

the sed command is to trick the compiler to dirty its cache.

note for other plateforms, the sed command is different, it is sed -i 's/gongtree_buttons/gongtree_buttons_new/g' tree.go

What did you see happen?

go build -v 46.99s user 2.44s system 371% cpu 13.320 total

What did you expect to see?

less than a few seconds

[seankhliao]

i believe this is working as expected as the standard library is not precompiled as part of the distribution but part of the user build cache.

[thomaspeugeot]

The first go build command reconstructs the cache, including the standard library.

The second build command, the one that is timed, only builds the tree package.

Therefore, i do not think this is the normal behavior. 

[cespare]

Reopening. Thanks for the easy reproducer @thomaspeugeot.

[seankhliao]

is there antivirus or other endpoint security software on the machine?

and where does it spend its time if you use go build -x

[thomaspeugeot]

is there antivirus or other endpoint security software on the machine?

No

[cespare]

I can reproduce locally on my Linux machine.

The time is spent actually running compile (i.e. gc).

I looked at a CPU profile and it's not obvious what's wrong, but there's a lot of GC. A heap profile shows a bunch of SSA-related allocations but I don't have enough experience debugging the compiler to know what's wrong based on that. The heap grows to 2.5 GB when compiling this which seems excessive? If I had to guess, something about this code causes the compiler to generate a rather large/inefficient internal representation of something.

[cespare]

BTW, it doesn't take 45s for me, but about 10s. I'm on a beefy desktop machine, though. I compared to a few other Go programs of similar size and compiling them (when deps are cached) takes roughly 200-500ms for me, so it's still >1 order of magnitude slower than I'd expect.

[seankhliao]

maybe it's the generics like with #51957 ? though there's less code here

[mauri870]

A brief look at cpu and mem profiles I can see that the compiler is taking a beating to compile all the switch statements over generics in the code.

Edit: a lot of time spent in ssa.Compile, cse, deadcode and prove passes

[thomaspeugeot]

@mdempsky , i prepared a branch "simplification-of-the-code" that is a stripped down version (48 lines instead of 1500 lines)

rm -rf thelongbuild
git clone https://github.com/thomaspeugeot/thelongbuild.git
cd thelongbuild
git checkout "simplification-of-the-code"
cd go/tree
go clean -cache
time go build -v
sed -i '' 's/NewNodeImpl/NewNodeImplNew/g' tree.go
time go build -v
cd ../../..

go build -v 43.19s user 2.18s system 381% cpu 11.894 total

I noticed 2 things:

1/ With the following line of code, one goes from below 1 second to above 43 seconds

    nodeCallback.FillUpForm = thelongbuild_probe.FillUpNamedFormFromGongstruct[T]

2/ 43 seconds is also the time it takes to build the probepackage

thomaspeugeot@MacBook-Pro-de-Thomas probe % time go build -v
github.com/thomaspeugeot/thelongbuild/go/probe
go build -v  44.76s user 2.32s system 376% cpu 12.509 total

By adding the line in the "tree" package", it seems that go rebuilds the whole "probe" package.

[egonelbre]

Some alternatives until things can be improved in the compiler. These may not fit your application, but it might fit someone else facing similar problems.

You might get help from not specializing on the funcs that mainly use switch any(x).(type) {. An example:

func FillUpNamedFormFromGongstruct[T models.Gongstruct](instance *T, probe *Probe, formStage *gongtable.StageStruct, formName string) {
    switch instancesTyped := any(instance).(type) {}
}

// convert to
func FillUpNamedFormFromGongstruct(instance any, probe *Probe, formStage *gongtable.StageStruct, formName string) {
    switch instancesTyped := instance.(type) {}
}

If you still want the type safety of the call, you can use:

func FillUpNamedFormFromGongstruct[T models.Gongstruct](instance *T, probe *Probe, formStage *gongtable.StageStruct, formName string) {
    fillUpNamedFormFromGongstruct(instance, probe, formStage, formName)
}

func fillUpNamedFormFromGongstruct(instance any, probe *Probe, formStage *gongtable.StageStruct, formName string) {
    switch instancesTyped := instance.(type) {}
}

If possible then you might be better of generating things as methods and using interfaces instead. This should allow the compiler to optimize things easier.

Similarly, there seem to be places where you can replace things with direct calls. For example:

func (stage *StageStruct) StageBranchTheBridge(thebridge *TheBridge) {
    // check if instance is already staged
    if IsStaged(stage, thebridge) {
        return
    }

// can be

    // check if instance is already staged
    if stage.IsStagedTheBridge(target) {
        return
    }

And I wouldn't be surprised if using interfaces / reflection more in the implementation you would get even better result.

[thomaspeugeot]

Hi @egonelbre , thanks for the pieces of advice. I will try to apply them. Most of the time, i rather use methods over function. However, most of this code is generic and using a method can be tricky (you can use a method on a generic struct). This whole code is a proof of concept that was started before the generics arrived.

BTW, I just found out the source of 50% of the build slowness. It happens that the function FillUpNamedFormFromGongstruct[T models.Gongstruct](instance *T, ... in the probe package that is called from the tree package is using a generic function GetReverseFieldOwnerName[T models.Gongstruct(...] in another package named orm. This generic function in the orm package is a generated file with 5754 lines of code with a lot of dead code. By removing the dead code in this function, one goes down to 626 lines. Then, the compilation time of the tree package goes to 20 seconds, a 50% saving (You can check the result in the branch "simplified-orm").

As a conclusion, I wonder if the go build slowness is still a problem. Are we not in a fringe use case with a lot of generated code ?

[egonelbre]

As a conclusion, I wonder if the go build slowness is still a problem. Are we not in a fringe use case with a lot of generated code?

It does seem to me on the fringe; however these situations can make it easier to discover general optimizations that help with regular codebases.