runtime: -quick tests aren't quick with reduced GOMAXPROCS

[bcmills]

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

~/go/src$ go version
go version devel go1.19-f89939a7c5 Tue Jul 12 13:46:24 2022 -0400 linux/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/src$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/usr/local/google/home/bcmills/.cache/go-build"
GOENV="/usr/local/google/home/bcmills/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/usr/local/google/home/bcmills/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/usr/local/google/home/bcmills"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/google/home/bcmills/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/google/home/bcmills/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="devel go1.19-f89939a7c5 Tue Jul 12 13:46:24 2022 -0400"
GCCGO="/usr/local/google/home/bcmills/bin/gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="c++"
CGO_ENABLED="1"
GOMOD="/usr/local/google/home/bcmills/go/src/go.mod"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build640773996=/tmp/go-build -gno-record-gcc-switches"

What did you do?

GO_TEST_SHORT=0 go tool dist test

What did you expect to see?

Passing tests.

What did you see instead?

A giant stack trace from a runtime test that timed out (overflowing my terminal's scrollback), followed by some passing maymorestack tests:

…

goroutine 27532570 [GC worker (idle)]:
runtime.gopark(0x3d101c40b34ec?, 0x1?, 0x4f?, 0x48?, 0x0?)
        /usr/local/google/home/bcmills/go/src/runtime/proc.go:363 +0xd6 fp=0xc0001a6f50 sp=0xc0001a6f30 pc=0x43f3b6
runtime.gcBgMarkWorker()
        /usr/local/google/home/bcmills/go/src/runtime/mgc.go:1235 +0xf1 fp=0xc0001a6fe0 sp=0xc0001a6f50 pc=0x4203d1
runtime.goexit()
        /usr/local/google/home/bcmills/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc0001a6fe8 sp=0xc0001a6fe0 pc=0x4773e1
created by runtime.gcBgMarkStartWorkers
        /usr/local/google/home/bcmills/go/src/runtime/mgc.go:1159 +0x25

goroutine 2806 [GC worker (idle), 1 minutes]:
runtime.gopark(0x3d0e866c6e3a0?, 0x3?, 0x6b?, 0x73?, 0x0?)
        /usr/local/google/home/bcmills/go/src/runtime/proc.go:363 +0xd6 fp=0xc000050f50 sp=0xc000050f30 pc=0x43f3b6
runtime.gcBgMarkWorker()
        /usr/local/google/home/bcmills/go/src/runtime/mgc.go:1235 +0xf1 fp=0xc000050fe0 sp=0xc000050f50 pc=0x4203d1
runtime.goexit()
        /usr/local/google/home/bcmills/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000050fe8 sp=0xc000050fe0 pc=0x4773e1
created by runtime.gcBgMarkStartWorkers
        /usr/local/google/home/bcmills/go/src/runtime/mgc.go:1159 +0x25
FAIL    runtime 300.087s
FAIL
2022/07/12 14:14:59 Failed: exit status 1

##### maymorestack=mayMoreStackPreempt
ok      runtime 67.672s
ok      reflect 1.315s
ok      sync    1.333s

##### maymorestack=mayMoreStackMove
skipped due to earlier error
skipped due to earlier error
skipped due to earlier error
go tool dist: FAILED

From comparing the output with a linux-amd64-longtest run on the build dashboard, I see that the test that timed out is probably this one (taken from the build dashboard):

##### GOMAXPROCS=2 runtime -cpu=1,2,4 -quick
ok  	runtime	638.620s

Note that although the dashboard builder sets GO_TEST_TIMEOUT_SCALE=5, this is the only test in the dashboard log that took more than 3 minutes.

Since the test explicitly sets the -quick flag, I expect it to instead be, well, “quick”. 😅
I suspect that something in the test is creating a hard-coded amount of concurrent work, when it should instead be scaling the work by GOMAXPROCS.

(attn @golang/runtime)

[prattmic]

They aren't particularly quick at higher GOMAXPROCS either. On my machine (GOMAXPROCS=12):

../bin/go test -count=1 runtime
ok      runtime 145.309s

../bin/go test -count=1 runtime -quick
ok      runtime 113.835s

../bin/go test -count=1 -short runtime -quick
ok      runtime 5.185s

../bin/go test -count=1 -short runtime
ok      runtime 12.046s

[prattmic]

$ ../bin/go test -count=1 runtime -quick | sed 's/\(.*\)(\(.*\))/\2 \1/' | sort -n -r | head -n 25
24.84s --- PASS: TestSmhasherWindowed 
11.56s --- PASS: TestSmhasherPermutation 
11.45s --- PASS: TestSmhasherAvalanche 
9.31s --- PASS: TestSmhasherTwoNonzero 
6.59s --- PASS: TestSchedLocalQueueEmpty 
5.81s --- PASS: TestChanSendSelectBarrier 
5.73s --- PASS: TestChanSendBarrier 
5.70s --- PASS: TestSmhasherSparse 
4.57s --- PASS: TestMemmoveOverlapLarge0x120000 
3.92s --- PASS: TestSmhasherSmallKeys 
3.49s --- PASS: TestSmhasherText 
3.47s --- PASS: TestMemmoveLarge0x180000 
3.32s --- PASS: TestDeferHeapAndStack 
3.27s --- PASS: TestStackMem 
2.93s --- PASS: TestMemmoveOverflow 
2.90s --- PASS: TestConcurrentReadsAfterGrowthReflect 
2.73s --- PASS: TestGdbPythonCgo 
2.60s --- PASS: TestGdbPython 
2.59s --- PASS: TestGdbPanic 
2.56s --- PASS: TestGdbConst 
2.56s --- PASS: TestGdbBacktrace 
2.55s --- PASS: TestGdbAutotmpTypes 
2.47s --- PASS: TestConcurrentReadsAfterGrowth 
1.76s --- PASS: TestSmhasherCyclic 
1.55s --- PASS: TestGoroutineProfile 

[prattmic]

(To be honest, I've never quite figured out what the intended difference between -quick and -short is supposed to be.)

[gopherbot]

Change https://go.dev/cl/417814 mentions this issue: runtime: skip slow smhasher tests with -quick

[prattmic]

At GOMAXPROCS=1 (and with https://go.dev/cl/417814):

12.79s --- PASS: TestChanSendSelectBarrier 
12.32s --- PASS: TestChanSendBarrier 
7.87s --- PASS: TestDeferPtrs 
6.64s --- PASS: TestSchedLocalQueueEmpty 
3.87s --- PASS: TestSmhasherSmallKeys 
3.86s --- PASS: TestDeferHeapAndStack 
3.35s --- PASS: TestSmhasherText 
3.25s --- PASS: TestStackMem 
3.21s --- PASS: TestGoroutineProfile 
2.62s --- PASS: TestDebugCallGrowStack 
2.35s --- PASS: TestMemmoveOverflow 
2.30s --- PASS: TestStopTheWorldDeadlock 
2.01s --- PASS: TestNoShrinkStackWhileParking 
1.90s --- PASS: TestMemmoveOverlapLarge0x120000 
1.77s --- PASS: TestSmhasherCyclic 
1.44s --- PASS: TestFastLog2 
1.02s --- PASS: TestChan 
1.01s --- PASS: TestSmhasherZeros 
1.00s --- PASS: TestGdbPythonCgo 
0.75s --- PASS: TestPreemptionAfterSyscall 
0.70s     --- PASS: TestPreemptionAfterSyscall/10µs 
0.70s --- PASS: TestMemmoveLarge0x180000 
0.65s --- PASS: TestCollisions 
0.42s --- PASS: TestGdbPython 
0.41s --- PASS: TestAtomicAlignment 

Total run time 81s.

[prattmic]

https://go.dev/cl/417814 reduces GO_TEST_SHORT=0 GO_TEST_TIMEOUT_SCALE=5 go tool dist test runtime:cpu124 from 360s to 200s on my machine.

[aclements]

I thought that -quick was supposed to be even faster than -short, but it's not like -quick implies -short and there are plenty of tests that check for -short without checking for -quick. So, I'm not sure these are serving any coherent purpose at this point.

[ianlancetaylor]

In an ordinary build the tests will be run with both -quick and -short=true (on a long test builder it will use -short=false instead). The point of -quick was to skip some tests that are not already skipped with -short. I think that it would fine to invoke the -quick tests with -short=true even when running on a long test builder.

[aclements]

Oh, you're right. cmd/dist doesn't make it obvious that -short is normally passed along with -quick (except on longtest). It doesn't seem to make much sense to pass -quick -short=false in any configuration.

[gopherbot]

Change https://go.dev/cl/417918 mentions this issue: cmd/dist: always pass -short=true with -quick