Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
bcmills opened this issue Jul 12, 2022 · 10 comments · Fixed by ferrmin/go#430
Closed

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

bcmills opened this issue Jul 12, 2022 · 10 comments · Fixed by ferrmin/go#430
Assignees
@ianlancetaylor
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone
Go1.19

Comments

@bcmills
Copy link
Contributor

bcmills commented Jul 12, 2022

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)
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jul 12, 2022
@bcmills bcmills added Testing An issue that has been verified to require only test changes, not just a test failure. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. compiler/runtime Issues related to the Go compiler and/or runtime. and removed compiler/runtime Issues related to the Go compiler and/or runtime. labels Jul 12, 2022
@prattmic
Copy link
Member

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
Copy link
Member

prattmic commented Jul 15, 2022 •
edited 

$ ../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
Copy link
Member

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

@gopherbot
Copy link

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

@prattmic
Copy link
Member

prattmic commented Jul 15, 2022 •
edited

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
Copy link
Member

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
Copy link
Member

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
Copy link
Contributor

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
Copy link
Member

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
Copy link

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

@prattmic prattmic added this to the Backlog milestone Jul 29, 2022
@ferrmin ferrmin mentioned this issue Jul 30, 2022
Merged
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Aug 1, 2022
@dmitshur dmitshur modified the milestones: Backlog, Go1.19 Aug 1, 2022
jproberts pushed a commit to jproberts/go that referenced this issue Aug 10, 2022
@ianlancetaylor @jproberts
cmd/dist: always pass -short=true with -quick
9e636df 
Fixes golang#53818

Change-Id: I190a8bcf50d92b9c10e9980e630ebb362d8b19ec
Reviewed-on: https://go-review.googlesource.com/c/go/+/417918
Run-TryBot: Ian Lance Taylor <iant@golang.org>
Auto-Submit: Ian Lance Taylor <iant@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>
Run-TryBot: Ian Lance Taylor <iant@google.com>
Reviewed-by: Cherry Mui <cherryyz@google.com>
@golang golang locked and limited conversation to collaborators Aug 1, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@ianlancetaylor ianlancetaylor

Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Milestone
Go1.19
Development

Successfully merging a pull request may close this issue.

cmd/dist: always pass -short=true with -quick golang/go
6 participants
@prattmic @dmitshur @aclements @ianlancetaylor @bcmills @gopherbot