runtime: scheduler sometimes starves a runnable goroutine on wasm platforms

[bcmills]

#!watchflakes
post <- goarch == "wasm" && pkg == "golang.org/x/net/http2" && test == "TestServer_Push_RejectAfterGoAway" && `timeout`

Go version

go version devel go1.23-1653833811 Fri Jan 19 19:23:40 2024 +0000 linux/amd64

Output of go env in your module/workspace:

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=''
GOTOOLCHAIN='local'
GOTOOLDIR='/usr/local/google/home/bcmills/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='devel go1.23-1653833811 Fri Jan 19 19:23:40 2024 +0000'
GCCGO='/usr/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='-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=/tmp/go-build1312466808=/tmp/go-build -gno-record-gcc-switches'

What did you do?

Add the following test to the time package:

func TestAfterFuncStarvation(t *testing.T) {
	var (
		wg sync.WaitGroup
		stop atomic.Bool
		c = make(chan bool, 1)
	)

	wg.Add(2)
	go func() {
		for !stop.Load() {
			c <- true
		}
		close(c)
		wg.Done()
	}()
	go func() {
		for range c {}
		wg.Done()
	}()

	AfterFunc(1 * Microsecond, func() { stop.Store(true) })
	wg.Wait()
}

Then run it using:

GOARCH=wasm GOOS=wasip1 go test time -run=TestAfterFuncStarvation -count=10000

What did you see happen?

~/go/src$ GOARCH=wasm GOOS=wasip1 go test time -run=TestAfterFuncStarvation -count=10000
panic: test timed out after 10m0s
running tests:
        TestAfterFuncStarvation (9m56s)

goroutine 13835 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2366 +0x44
created by time.goFunc
        /usr/local/google/home/bcmills/go/src/time/sleep.go:177 +0x5

goroutine 1 [chan receive]:
testing.(*T).Run(0x178b040, {0x6a007, 0x13}, 0xde460)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1750 +0x44
testing.runTests.func1(0x178b040)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2161 +0x3
testing.tRunner(0x178b040, 0x1499c80)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1689 +0xd
testing.runTests(0x140a2a0, {0x37c140, 0x7f, 0x7f}, {0xc162d83908280698, 0x8bb3084da4, 0x37faa0})
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2159 +0x49
testing.(*M).Run(0x144e140)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2027 +0x6e
main.main()
        _testmain.go:445 +0x9

goroutine 13833 [runnable]:
time_test.TestAfterFuncStarvation.func2()
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:102 +0x4
created by time_test.TestAfterFuncStarvation in goroutine 13831
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:101 +0xd

goroutine 13831 [semacquire, 9 minutes]:
sync.runtime_Semacquire(0x1790198)
        /usr/local/google/home/bcmills/go/src/runtime/sema.go:62 +0x2
sync.(*WaitGroup).Wait(0x1790190)
        /usr/local/google/home/bcmills/go/src/sync/waitgroup.go:116 +0xf
time_test.TestAfterFuncStarvation(0x178b1e0)
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:107 +0x12
testing.tRunner(0x178b1e0, 0xde460)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1689 +0xd
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1742 +0x43

goroutine 13832 [chan send]:
time_test.TestAfterFuncStarvation.func1()
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:96 +0x3
created by time_test.TestAfterFuncStarvation in goroutine 13831
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:94 +0x9

goroutine 13834 [runnable]:
time_test.TestAfterFuncStarvation.func3()
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:106
created by time.goFunc
        /usr/local/google/home/bcmills/go/src/time/sleep.go:177 +0x5
FAIL    time    600.293s
FAIL

What did you expect to see?

The test completes 1000 iterations on wasip1/wasm in about 1.2 seconds on my machine, so 10000 iterations should only take ~12 seconds:

~/go/src$ GOARCH=wasm GOOS=wasip1 go test time -run=TestAfterFuncStarvation -count=1000
ok      time    1.228s

Running native code on linux/amd64 is much faster still, but that's to be expected:

go test time -run=TestAfterFuncStarvation -count=10000
ok      time    0.587s

(attn @golang/wasm)

[bcmills]

This also affects js/wasm: 100 iterations take <600ms, so 1000 iterations should take <6s (but times out after a full minute):

~/go/src$ GOARCH=wasm GOOS=js go test time -run=TestAfterFuncStarvation -count=100
ok      time    0.519s

~/go/src$ GOARCH=wasm GOOS=js go test time -run=TestAfterFuncStarvation -count=1000 -timeout=1m
panic: test timed out after 1m0s
running tests:
        TestAfterFuncStarvation (1m0s)

goroutine 2980 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2366 +0x44
created by time.goFunc
        /usr/local/google/home/bcmills/go/src/time/sleep.go:177 +0x5

goroutine 1 [chan receive]:
testing.(*T).Run(0x151fa00, {0x6e19f, 0x17}, 0xe09b0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1750 +0x44
testing.runTests.func1(0x151fa00)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2161 +0x3
testing.tRunner(0x151fa00, 0x1493c80)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1689 +0xd
testing.runTests(0x140a360, {0x37fc60, 0x7f, 0x7f}, {0xc162d954b7abb580, 0xdf9e00901, 0x38b6e0})
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2159 +0x49
testing.(*M).Run(0x144c3c0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2027 +0x6e
main.main()
        _testmain.go:445 +0x9

goroutine 6 [waiting]:
runtime.gopark(0x0, 0x0, 0x0, 0x0, 0x1)
        /usr/local/google/home/bcmills/go/src/runtime/proc.go:402 +0x25
runtime.handleEvent()
        /usr/local/google/home/bcmills/go/src/runtime/lock_js.go:296 +0x25
runtime.goexit({})
        /usr/local/google/home/bcmills/go/src/runtime/asm_wasm.s:434 +0x1

goroutine 2976 [semacquire]:
sync.runtime_Semacquire(0x140c188)
        /usr/local/google/home/bcmills/go/src/runtime/sema.go:62 +0x2
sync.(*WaitGroup).Wait(0x140c180)
        /usr/local/google/home/bcmills/go/src/sync/waitgroup.go:116 +0xf
time_test.TestAfterFuncStarvation(0x151fba0)
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:107 +0x12
testing.tRunner(0x151fba0, 0xe09b0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1689 +0xd
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1742 +0x43

goroutine 2977 [chan send]:
time_test.TestAfterFuncStarvation.func1()
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:96 +0x3
created by time_test.TestAfterFuncStarvation in goroutine 2976
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:94 +0x9

goroutine 2978 [runnable]:
time_test.TestAfterFuncStarvation.func2()
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:102 +0x4
created by time_test.TestAfterFuncStarvation in goroutine 2976
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:101 +0xd

goroutine 2979 [runnable]:
time_test.TestAfterFuncStarvation.func3()
        /usr/local/google/home/bcmills/go/src/time/sleep_test.go:106
created by time.goFunc
        /usr/local/google/home/bcmills/go/src/time/sleep.go:177 +0x5
FAIL    time    60.358s
FAIL

[prattmic]

Does this also affect linux-amd64 if GOMAXPROCS=1?

[bcmills]

No, it does not: if I update the test to explicitly call runtime.GOMAXPROCS(1), it continues to pass after even 100000 runs.

[gopherbot]

Change https://go.dev/cl/557037 mentions this issue: net: work around runtime scheduler starvation on js and wasip1

[gopherbot]

Change https://go.dev/cl/557038 mentions this issue: time: add a regression test for time.AfterFunc goroutine starvation

[prattmic]

At a theoretical level, this doesn't surprise me, and I would expect it to impact linux-amd64 GOMAXPROCS=1.

This test always has at least one runnable goroutine (one of the channel send/recv goroutines). In fact, because the channel is buffered in theory both goroutines may be runnable all of the time.

When the timer fires, a third goroutine will become runnable [1].

We have one thread on which to run three goroutines, so there must be some scheduling delay. Go does not have a real-time scheduler, or even a best-effort deadline-based scheduler, so it can theoretically have unbounded scheduling delay.

Readying a goroutine typically puts it on the head of the run queue to get it to run soon. But since that applies to almost every ready, the timer firing could put goroutine 3 on the head of the run queue, and then goroutine 1 or 2 could replace the head before the scheduler runs again.

If you dump the /sched/latencies:seconds histogram from runtime/metrics, I'd expect to see a long tail of long scheduling delays.

There are certainly many improvements that could go into the scheduler to try to make this situation better (#51071 comes to mind).

The more interesting case would be if this is actually completely stuck. i.e., the timer expiration or ready goroutine was somehow lost altogether. Figuring that out by running a test is a bit of a halting problem situation, but looking at runtime/metrics is probably a good start. Do we have many cases of long scheduling delay (but not enough to cause a timeout)? Or do things seem totally fine until one case gets stuck forever?

[1] We always run timers before looking for other work in the scheduler, so the timer should always fire. But an AfterFunc timer just starts a goroutine to run the func, which is the third goroutine.

[bcmills]

I agree that the runtime is theoretically allowed to produce this behavior according to the language spec.

However, the addition of non-cooperative preemption (#24543) set up a strong expectation that every runnable goroutine will eventually be scheduled, and resolved a large number of previous scheduler fairness issues (linked from that proposal).

We also explicitly made mutex locking starvation-free in #13086. To me, that suggests that this sort of goroutine starvation is not intended behavior.

This sort of starvation shows up in realistic programs that use time.AfterFunc to interrupt two or more running goroutines, as might be the case in a benchmark or stress-test. (See, for example, #65177.) It is sometimes possible to work around that starvation by making explicit calls to runtime.Gosched (as in https://go.dev/cl/557037), but arguably that's exactly the sort of explicit scheduler management that #24543 was intended to address.

[prattmic]

I think I poorly worded my previous message and came across too strongly. I don't think this is good behavior, I meant that there are two broad classes this problem may be in:

1. There is nothing fundamentally wrong, but the existing design is producing poor behavior.
2. Something is fundamentally broken, and this wakeup is lost/gone and no amount of waiting would resolve it.

[bcmills]

Ah, yeah. I think the evidence so far supports (1) — the goroutine dumps from the timed-out tests list the AfterFunc goroutine as runnable, it just isn't actually being run.

(The fact that it is listed as runnable, and the fact that adding an explicit runtime.Gosched in https://go.dev/cl/557037 seems to fix the starvation there, suggest that the goroutine is successfully being marked schedulable, it just isn't getting scheduled.)

[Jorropo]

I thought this could be working on amd64 because the goroutines are being non-cooperatively preempted by GC which could randomly restart execution. But trying out with GOGC=off GOMAXPROCS=1 doesn't let me reproduce.