testing/synctest: timers scheduled for the same instant always fire in creation order

[glycerine]

Go version

go1.24.3 GOEXPERIMENT=synctest on darwin/amd64

Output of go env in your module/workspace:

$ go env
AR='ar'
CC='clang'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='clang++'
GCCGO='gccgo'
GO111MODULE='auto'
GOAMD64='v1'
GOARCH='amd64'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/Users/jaten/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/jaten/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/b6/q5ms8t4x5cjcpcpyjrb1h91c0000gn/T/go-build4159139888=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/Users/jaten/go/src/github.com/glycerine/reflect_not_random_synctest/go.mod'
GOMODCACHE='/Users/jaten/go/pkg/mod'
GONOPROXY='github.com/glycerine/*'
GONOSUMDB='github.com/glycerine/*'
GOOS='darwin'
GOPATH='/Users/jaten/go'
GOPRIVATE='github.com/glycerine/*'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go1.24.3'
GOSUMDB='sum.golang.org'
GOTELEMETRY='off'
GOTELEMETRYDIR='/Users/jaten/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go1.24.3/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.24.3'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

Hi @neild

I'm stoked that synctest was approved. Congratulations!

I noticed a minor randomization failure in reflect.Select under synctest.

Probably worth fixing before go 1.25; assuming I'm not just doing something dumb that caused this...

Reproducer:

https://github.com/glycerine/reflect_not_random_synctest

What did you see happen?

The first call to reflect.Select() always returns case 0 under synctest.

Without synctest, it appears properly pseudo-randomized.

See

https://github.com/glycerine/reflect_not_random_synctest/blob/master/README.md

What did you expect to see?

The first reflect.Select() call should be random, just like subsequent ones; as when not running under synctest.

[gabyhelp]

Related Issues

• testing/synctest: does not always reset fake time between tests. #73615 (closed)
• runtime: select is not fair #21806 (closed)

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

[glycerine]

Happens on Linux too; ubuntu 18/amd64.

Considering how, in this previous issue gabby point to, Ian noted that reflect.Select failure to be random also indicated regular, ordinary select was also failing to be random, perhaps I should not have called this minor.

gabby saw: #21806

[zigo101]

In practice, I find that I often hope select order are prioritized instead of randomized.

[mknyszek]

CC @neild

[neild]

This actually has nothing to do with select or reflect.Select's randomness, or not directly.

When a goroutine executes a select statement, the runtime picks a random case which can make progress. If none of the cases can make progress, the runtime parks the goroutine and wakes it when a case can make progress.

When you select on two timer channels where the timer has fired, the runtime picks a random case.

When you select on two timer channels where the timer has not yet fired, the runtime parks the current goroutine and wakes it when one of those timers fires.

If you create two timers using real time (no synctest) with a 0 or very short timeout and select on their channels, the select will pick a random case. However, if you create two timers with a longer timeout (10ms, say) and immediately select on thir channels, select will always pick the first timer to be created. This is because the select statement will park the current goroutine, and will be woken by the first timer to fire.

If you change the provided example to create timers with a 10ms timeout rather than a 0 timeout, you'll observe that the first timer created is picked by select every time.

It's probably worth randomizing the order in which timers at the same instant fire within a synctest bubble, but outside of the case of NewTimer(0) (or a non-zero but very short timeout which immediately expires, such as 1ns), I don't think the behavior of timers in a synctest bubble is very different from that of them outside one.

[glycerine]

When you select on two timer channels where the timer has fired, the runtime picks a random case.

The reproducer/test I wrote shows that this is not the case under synctest, right?

For 10,000 times in a row, the first case in the select is the only one ever chosen.

This is not random.

Here are five runs under synctest, with the print placed after the reflect.Select. Pay attention to the i=0 line, notice how chosen is always 0.

run 1

Compilation started at Wed May 28 18:59:27

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z  <<<< chosen 0
on i=1, chosen=3, timer 1: 2000-01-01T00:00:00.000Z
on i=2, chosen=6, timer 2: 2000-01-01T00:00:00.000Z
...

run 2

Compilation started at Wed May 28 19:01:03

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z <<<<< chosen 0
on i=1, chosen=6, timer 1: 2000-01-01T00:00:00.000Z
on i=2, chosen=9, timer 2: 2000-01-01T00:00:00.000Z
...

run 3

Compilation started at Wed May 28 19:01:21

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z <<<<< chosen 0
on i=1, chosen=8, timer 1: 2000-01-01T00:00:00.000Z
on i=2, chosen=4, timer 2: 2000-01-01T00:00:00.000Z
...

run 4

Compilation started at Wed May 28 19:01:37

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z <<<<< chosen 0
on i=1, chosen=4, timer 1: 2000-01-01T00:00:00.000Z
on i=2, chosen=1, timer 2: 2000-01-01T00:00:00.000Z
...

run 5

Compilation started at Wed May 28 19:01:53

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z <<<<< chosen 0
on i=1, chosen=2, timer 1: 2000-01-01T00:00:00.000Z
on i=2, chosen=6, timer 2: 2000-01-01T00:00:00.000Z
...

For contrast, here are 5 runs under realtime. Again, look at the chosen at i=0.

run 1, realtime

Compilation started at Wed May 28 19:04:22

go test -v
faketime = false
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=4, timer 0: 2025-05-29T00:04:22.322Z <<<< chosen 4
on i=1, chosen=0, timer 1: 2025-05-29T00:04:22.322Z
on i=2, chosen=6, timer 2: 2025-05-29T00:04:22.322Z
...

run 2, realtime

Compilation started at Wed May 28 19:04:52

go test -v
faketime = false
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=1, timer 0: 2025-05-29T00:04:53.032Z <<<< chosen 1
on i=1, chosen=6, timer 1: 2025-05-29T00:04:53.032Z
on i=2, chosen=9, timer 2: 2025-05-29T00:04:53.032Z
...

run 3, realtime

Compilation started at Wed May 28 19:05:12

go test -v
faketime = false
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=8, timer 0: 2025-05-29T00:05:12.992Z <<<< chosen 8
on i=1, chosen=7, timer 1: 2025-05-29T00:05:12.992Z
on i=2, chosen=1, timer 2: 2025-05-29T00:05:12.992Z
...

run 4, realtime

Compilation started at Wed May 28 19:05:30

go test -v
faketime = false
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2025-05-29T00:05:30.448Z <<< chosen 0
on i=1, chosen=3, timer 1: 2025-05-29T00:05:30.448Z
on i=2, chosen=5, timer 2: 2025-05-29T00:05:30.448Z
...

run 5, realtime

Compilation started at Wed May 28 19:06:20

go test -v
faketime = false
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=4, timer 0: 2025-05-29T00:06:20.216Z <<<< chosen 4
on i=1, chosen=2, timer 1: 2025-05-29T00:06:20.216Z
on i=2, chosen=3, timer 2: 2025-05-29T00:06:20.216Z
...

[glycerine]

I see what you are saying about firing in creation order now. That is the same in both
synctest and realtime. I'm still unclear on why timer 0 is sometimes case 0 (synctest) and sometimes case 4 (realtime)...

from the test code, timer 0 should always be case 0. Am I seeing a bug in the reflect reporting (of the chosen case from reflect.Select; I expect case k == timer k always for all ten values of k...)?

I'd really like timers at the same deadline to not fire in creation order, but rather in pseudo random order... unless you want to guarantee creation-order firing for the foreseeable future. cf #73850

[glycerine]

Arg. I see a mistake I made now. I was printing loop timer and not the chosen case timer. Disregard my comments about case and timer not aligning. I've applied that fix to the repro repo. now chosen and timer are in alignment.

[glycerine]

With my bug corrected, here are 5 sample synctest runs.

Timers are numbered in the order they are created; and assigned to the same cases (in the select) as their creation order.

The non-random-ness that I see is that the first-created timer is always selected first.

After that, it appears to be randomized. I have not run any statistical tests on that; its just a rough impression.

For example, the first run shows i=1 of timer 7. If timers where scheduled in creation order, you would expect timer 1 to run next.

github.com/glycerine/reflect_not_random_synctest
version
1ba00f130fc9573e2ff5496176f69be0e0245bc6

5 runs under synctest:

run S1, synctest

Compilation started at Thu May 29 06:32:45

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z
on i=1, chosen=7, timer 7: 2000-01-01T00:00:00.000Z
on i=2, chosen=9, timer 9: 2000-01-01T00:00:00.000Z
on i=3, chosen=5, timer 5: 2000-01-01T00:00:00.000Z


run S2, synctest

Compilation started at Thu May 29 06:33:05

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z
on i=1, chosen=4, timer 4: 2000-01-01T00:00:00.000Z
on i=2, chosen=6, timer 6: 2000-01-01T00:00:00.000Z
on i=3, chosen=8, timer 8: 2000-01-01T00:00:00.000Z


run S3, synctest

Compilation started at Thu May 29 06:33:26

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z
on i=1, chosen=2, timer 2: 2000-01-01T00:00:00.000Z
on i=2, chosen=6, timer 6: 2000-01-01T00:00:00.000Z
on i=3, chosen=4, timer 4: 2000-01-01T00:00:00.000Z
on i=4, chosen=8, timer 8: 2000-01-01T00:00:00.000Z

run S4, synctest

Compilation started at Thu May 29 06:33:43

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z
on i=1, chosen=2, timer 2: 2000-01-01T00:00:00.000Z
on i=2, chosen=6, timer 6: 2000-01-01T00:00:00.000Z
on i=3, chosen=8, timer 8: 2000-01-01T00:00:00.000Z

run S5, synctest

Compilation started at Thu May 29 06:34:01

GOTRACEBACK=all GOEXPERIMENT=synctest go test -v
faketime = true
=== RUN   Test800_synctest_reflect_select
on i=0, chosen=0, timer 0: 2000-01-01T00:00:00.000Z
on i=1, chosen=7, timer 7: 2000-01-01T00:00:00.000Z
on i=2, chosen=8, timer 8: 2000-01-01T00:00:00.000Z
on i=3, chosen=6, timer 6: 2000-01-01T00:00:00.000Z
on i=4, chosen=2, timer 2: 2000-01-01T00:00:00.000Z