x/tools/go/ssa: TestTypeparamTest slowed from < 1 second to > 25 seconds since CL 614975

[millerresearch]

Go version

go version go1.22.5 linux/amd64

Output of go env in your module/workspace:

O111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/miller/.cache/go-build'
GOENV='/home/miller/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/miller/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/miller/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/miller/goroot'
GOSUMDB='sum.golang.org'
GOTMPDIR='/home/miller/gotest'
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/miller/goroot/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.22.5'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/home/miller/tools/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 -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/home/miller/gotest/go-build3760712854=/tmp/go-build -gno-record-gcc-switches'

What did you do?

In x/tools directory, go test -short -count 1 -run TestTypeparamTest ./go/ssa

What did you see happen?

Since CL 614975 this test has slowed by more than 50x:

miller@m720q:~/tools$ git checkout 8adb6e83d^
Previous HEAD position was 8adb6e83d go/ssa: migrate TestTypeparamTest away from loader
HEAD is now at 7bb384dcf gopls/internal/test/integration/bench: add an IWL test that opens files
miller@m720q:~/tools$ time go test -short -timeout=60m -count 1 -run TestTypeparamTest ./go/ssa
ok  	golang.org/x/tools/go/ssa	0.452s

real	0m0.675s
user	0m1.032s
sys	0m0.162s
miller@m720q:~/tools$ git checkout 8adb6e83d
Previous HEAD position was 7bb384dcf gopls/internal/test/integration/bench: add an IWL test that opens files
HEAD is now at 8adb6e83d go/ssa: migrate TestTypeparamTest away from loader
miller@m720q:~/tools$ time go test -short -count 1 -run TestTypeparamTest ./go/ssa
ok  	golang.org/x/tools/go/ssa	25.829s

real	0m26.178s
user	1m3.884s
sys	0m7.800s

On plan9-arm, where the unfortunate migration to LUCI has made everything slower by splitting the goroot files and test execution onto separate machines across the network, the slowdown is more than 100x and causes the x/tools test to timeout and fail:

Previous HEAD position was 8adb6e83d go/ssa: migrate TestTypeparamTest away from loader
HEAD is now at 7bb384dcf gopls/internal/test/integration/bench: add an IWL test that opens files
miller@m720q:~/tools$ GOOS=plan9 GOARCH=arm time go test -short -count 1 -run TestTypeparamTest ./go/ssa
ok  	golang.org/x/tools/go/ssa	6.635s
1.139u 0.788s 6.875r 	 go test -short -count 1 ...
miller@m720q:~/tools$ git checkout 8adb6e83d
Previous HEAD position was 7bb384dcf gopls/internal/test/integration/bench: add an IWL test that opens files
HEAD is now at 8adb6e83d go/ssa: migrate TestTypeparamTest away from loader
miller@m720q:~/tools$ GOOS=plan9 GOARCH=arm time go test -short -timeout=60m -count 1 -run TestTypeparamTest ./go/ssa
ok  	golang.org/x/tools/go/ssa	778.342s
76.031u 66.000s 778.591r 	 go test -short -timeout=60m -count ...

What did you expect to see?

The comment at the head of function TestTypeparamTest says:

	// Tests use a fake goroot to stub out standard libraries with declarations in
	// testdata/src. Decreases runtime from ~80s to ~1s.

However the code to do this seems to have been removed by CL 614975, making the comment incorrect and execution time very much slower.

[gabyhelp]

Related Issues and Documentation

• runtime: `-quick` tests aren't quick with reduced GOMAXPROCS #53818 (closed)
• go/internal/gcimporter: fix TestImportStdLib
• x/build: run standard library tests without -short #17472 (closed)
• go/internal/srcimporter: use the 'go' command from the Importer's GOROOT
• x/tools/go/packages: LoadSyntax performance after LoadMode option split into Need constants #31930 (closed)
• test,internal/testdir: don't set GOOS/GOARCH
• misc/cgo/test: use alternate path for 18146 when coverage enabled
• x/tools: multiple tests timing out on `darwin-amd64-longtest` #59634
• cmd/go: use package index for std in load.loadPackageData
• internal/testenv: avoid rebuilding all of std in WriteImportcfg

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[cagedmantis]

cc @timothy-king

[adonovan]

Thanks for analyzing this. We should definitely make this test faster, reverting the CL if necessary. @xieyuschen

There are about 300 single-file tests in the GOROOT/test/testparam directory. We should be running them in parallel. However, that alone won't make things faster because (I observe) the go list command executed by packages.Load is very highly contended: when run in parallel, many commands take over 7s to execute. When executed sequentially, the running time is clearly bimodal: usually it's around 70ms but often it is slightly more than 1.0s.

@matloob @samthanawalla I vaguely recall that the go command, under some circumstances, deliberately sleeps for 1s to ensure a "happens before" relationship between file timestamps on file systems with very coarse mtime quantization (e.g. 1s on WSL). If we could somehow avoid that sleep, the parallel test would run in about 300 x 80ms / 16 cores = 1.5s.

[adonovan]

In other news: this test assumes that GOROOT/test is accessible, which is not the case for a downloaded toolchain. (The builders and most dev machines have a real GOROOT, which is why we didn't notice this till @pjweinb reported it today.)
We should make the test skip if there is no local GOROOT; the builders will enforce that the tests pass.

[gopherbot]

Change https://go.dev/cl/623135 mentions this issue: go/ssa: speed up TestTypeparamTest by loading tests once

[xieyuschen]

Thanks for your analysis:) @millerresearch

I vaguely recall that the go command... deliberately sleeps for 1s to ensure a "happens before" relationship between file timestamps on file systems with very coarse mtime quantization... run in about 300 x 80ms / 16 cores = 1.5s.

I don't know this part but looks like this optimization of go list for packages.Load requires a discussion by maintainers. So I try to speed it up by loading all packages in a single packages.Load call in CL 623135. It's great if we can speed up go list itself:)

this test assumes that GOROOT/test is accessible, which is not the case for a downloaded toolchain

I have fixed this in the same CL for test TestTypeparamTest, and I will check whether the other test cases have this issue. Btw, I didn't find the issue about this problem so I didn't link it in the CL.

Thanks!

[millerresearch]

It's great if we can speed up go list itself:)

That would be a big benefit, especially for builders with slower filesystems.