cmd/go: spends a long time loading packages

[fumin]

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

$ go version
go version go1.20.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 GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\a3367\AppData\Local\go-build
set GOENV=C:\Users\a3367\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\a3367\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\a3367\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.20.4
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\Users\a3367\work\web\go.mod
set GOWORK=
set CGO_CFLAGS=-O2 -g
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-O2 -g
set CGO_FFLAGS=-O2 -g
set CGO_LDFLAGS=-O2 -g
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=C:\Users\a3367\AppData\Local\Temp\go-build1854760467=/tmp/go-build -gno-record-gcc-switches

What did you do?

I tried to build a program with the following go.mod and go.sum.

gomod.zip

and did a profiling of the build process with the following command:

go build -debug-trace="build.trace" .\cmd\server\GoServer.go

and got the following trace:

build_trace.zip

then I visualized the trace in https://ui.perfetto.dev/

P.S. I have asked on both go-nuts and golangbridge, but it seems that the community does not have an answer either. https://groups.google.com/g/golang-nuts/c/72OsIXVcmCs https://forum.golangbridge.org/t/very-slow-build-taking-lots-of-time/32149

What did you expect to see?

I expect to see the build finish in 7 seconds, which is indicated by the section exec.Builder.Do in the trace.

What did you see instead?

I saw the build taking an entire 40 seconds! with most the time spent in load.PackagesAndErrors. A closer look suggests that the culprit might be in the following functions:

• modfetch.download
• modload.loadImport

Since I can build my program without internet connection, this rules out network issues. Why is module loading taking so much time (there're only 122 lines in my go.sum)? How can we reduce the time spent in module loading, or even better eliminate these loading operations?

For many many many years, the most exciting and unbeatable feature of Go is its consistently fast build times on all my programs. I am kind of surprised that not only is building with the latest release slow, but most of the time is spent on loading modules, instead of actually compiling.

Update 2023/07/07

As described in this comment, the build can be made fast when building with go mod vendor. Under vendor mode, the build takes 10s, which is a 4x improvement over the original 40s. However, there's still a mysterious 6s gap in the very beginning, and eliminating this do nothing gap would make build times drop to 4s, which is a 10x improvement! However, I don't know what causes this gap neither how to remove it. Is this gap due to some sort of warm up or unnecessary checks during start up?

[seankhliao]

have you ruled out your antivirus being responsible for the slowness

[fumin]

have you ruled out your antivirus being responsible for the slowness

This is an interesting hypothesis. I do have a Trendmicro installed, and I am sometimes asked to trust the built executable.

But how can I detect that the build slowness is due to the antivirus, especially not in the compilation but in the load module phase? I am aware the antivirus is constantly running in the background, but since my laptop has 4 cores, I always have around 80% of CPU available to me according to Windows task manager. Is there a known pathway for the antivirus to affect exclusively the load module phase rather than the CPU intensive actual compilation phase? What makes the load module phase so special?

[seankhliao]

it downloads and opens a lot of files, antivirus may want to scan those as untrusted content.

[fumin]

it downloads and opens a lot of files, antivirus may want to scan those as untrusted content.

This is an interesting hypothesis. Alas, I am on a corporate computer, and thus can't do much about the antivirus. However, I would like to note that on the same computer, I can read 500MB in 300ms from disk, so whatever the antivirus is interfering with IO operations, it may be neglibible?

I do notice something special in the traces, there are large gaps between the modfetch.download phase:

For example, there's a large gap of 6 seconds between:

• modfetch.download golang.org/x/text@v0.3.8, start time 13s 226ms, duration 834us
• modfetch.download golang.org/x/image, start time 19s 444ms, duration 1ms 247us

I wonder what is the cause of these seamingly doing nothing gaps? Since I can build without internet connection, I presume modfetch.download should be no-ops, and thus the antivirus should not be in the loop. Am I missing something?

[seankhliao]

I assume it's still opening a lot of files (which may be checked) in that time, even if it doesn't have to download them from the internet. Or you have a slow filesystem (lots of small reads has a different performance profile than one big sequential read).

[fumin]

Interestingly, the build is fast when building from the vendor folder! As shown in the trace below, load.PackagesAndErrors now takes only 8s, as opposed to the 32s in the normal build:

trace.zip

What this means, is that there's nothing wrong with my computer, and that go builds can be fast. Indeed, except recently Go builds have always been fast, and this snappiness regardless of machine, platform or program size, is why I love Go so much for so many years since before Go 1.0.

Alas, there's still room for improvement, as can be seen in the trace above, there's a mysterious 6s second gap in the very beginning before load.PackagesAndErrors does it first thing modload.loadImport bytes. Why this gap? Without this seemingly doing nothing gap, load.PackagesAndErrors actually takes only 2s, and the overall build sould be able to complete in 4s, a 10x improvement over the original 40s!!! How can we get further granularity of what's going on inside load.PackagesAndErrors? What can be done to eliminate all do nothing gaps in go build entirely?

P.S. the exact steps for building with the vendor directory is:

go mod vendor  # copy source files of all dependacies into the vendor subfolder.
go build cmd\server\GoServer.go  # build as usual.

[seankhliao]

you can build and run a modified tool chain with more detailed trace spans covering the parts that you think are interesting.