runtime: TestReadMetricsSched failures on s390x since CL 721002

[srinivas-pokala]

Go version

go version go1.26-devel_c079dd13c0 Thu Nov 27 05:54:25 2025 -0800 linux/s390x

Output of go env in your module/workspace:

AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='s390x'
GOAUTH='netrc'
GOBIN='/root/go/bin'
GOCACHE='/root/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/root/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -march=z13 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build3600178475=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='s390x'
GOHOSTOS='linux'
GOINSECURE=''
GOMOD='/root/go_compiler/dev/go_src/src/go.mod'
GOMODCACHE='/root/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/root/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/root/go_compiler/dev/go_src'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/root/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/root/go_compiler/dev/go_src/pkg/tool/linux_s390x'
GOVCS=''
GOVERSION='go1.26-devel_c079dd13c0 Thu Nov 27 05:54:25 2025 -0800'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

I ran ./all.bash on tip of the master,

What did you see happen?

TestReadMetricsSched failing with below verbose:

--- FAIL: TestReadMetricsSched (0.16s)
    metrics_test.go:1581: /tmp/go-build2389263017/testprog.exe SchedMetrics: exit status 1
    metrics_test.go:1584: output:
        === Checking "base"
                /sched/goroutines/not-in-go:goroutines: 0
                /sched/goroutines/runnable:goroutines: 1
                /sched/goroutines/running:goroutines: 1
                /sched/goroutines/waiting:goroutines: 132
                /sched/goroutines-created:goroutines: 134
                /sched/threads/total:threads: 37
        === Checking "created"
                /sched/goroutines/not-in-go:goroutines: 0
                /sched/goroutines/runnable:goroutines: 0
                /sched/goroutines/running:goroutines: 11
                /sched/goroutines/waiting:goroutines: 133
                /sched/goroutines-created:goroutines: 144
                /sched/threads/total:threads: 37
        === Checking "running"
                /sched/goroutines/not-in-go:goroutines: 0
                /sched/goroutines/runnable:goroutines: 0
                /sched/goroutines/running:goroutines: 11
                /sched/goroutines/waiting:goroutines: 133
                /sched/goroutines-created:goroutines: 144
                /sched/threads/total:threads: 37
                /sched/threads/total:threads too high; 37 > 19
        === Checking "runnable"
                /sched/goroutines/not-in-go:goroutines: 0
                /sched/goroutines/runnable:goroutines: 10
                /sched/goroutines/running:goroutines: 1
                /sched/goroutines/waiting:goroutines: 133
                /sched/goroutines-created:goroutines: 144
                /sched/threads/total:threads: 37
        === Checking "not-in-go"
                /sched/goroutines/not-in-go:goroutines: 10
                /sched/goroutines/runnable:goroutines: 0
                /sched/goroutines/running:goroutines: 1
                /sched/goroutines/waiting:goroutines: 133
                /sched/goroutines-created:goroutines: 154
                /sched/threads/total:threads: 37
        === Checking "waiting"
                /sched/goroutines/not-in-go:goroutines: 0
                /sched/goroutines/runnable:goroutines: 0
                /sched/goroutines/running:goroutines: 1
                /sched/goroutines/waiting:goroutines: 1133
                /sched/goroutines-created:goroutines: 1154
                /sched/threads/total:threads: 49

It appears the failures began with the commit: a18aff8

What did you expect to see?

It should pass all the test's.

[srinivas-pokala]

CC @prattmic @mknyszek

[prattmic]

Do you know what GOMAXPROCS is when this test runs? (We should probably log it)

The total thread count is 37 even in the "base" case before the test does much. It is after a runtime.GC() call. Presumably https://go.dev/cl/721002 is causing more threads to spin up to run the GC, but it's not totally obvious why.

One theory: previously GC threads would spin up one at a time. i.e., one thread in findRunnable would decide it needs to do GC work, and then call wakep to wake another thread in case there is additional work (GC or user goroutines). This continues one at a time until all GC workers are running. It's possible that the heap in this program is so small that the GC actually finished before we managed to spin up enough threads for all GC workers [1]. Now we are starting them proactively, so we'll always start enough.

One way to confirm this would be with an execution trace before and after https://go.dev/cl/721002. You can just add runtime/trace.Start/Stop calls to https://cs.opensource.google/go/go/+/master:src/runtime/testdata/testprog/schedmetrics.go;l=30;drc=ac2ec82172799b88c057bb9ded6fe24e7909e860, and run go run runtime/testdata/testprog SchedMetrics.

[1] Why s390x only, though? Is thread creation particularly slow there?

[dmitshur]

CC @golang/s390x.

[gopherbot]

Change https://go.dev/cl/725660 mentions this issue: runtime/internal/testprog: log initial SchedMetrics GOMAXPROCS

[gopherbot]

Change https://go.dev/cl/726642 mentions this issue: runtime: relax threadsSlack in TestReadMetricsSched