context: WithTimeout scheduling is less deterministic than time.Timer on Windows

[vellotis]

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

I have tried with go version go1.15.2 windows/amd64 and go version go1.16 windows/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 env
set GO111MODULE=on
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\user\AppData\Local\go-build
set GOENV=C:\Users\user\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Projects\Go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Projects\Go
set GOPRIVATE=
set GOPROXY=
set GOROOT=C:\Tools\Go\go1.16
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Tools\Go\go1.16\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.16
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=NUL
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=C:\Users\user\AppData\Local\Temp\go-build2862485594=/tmp/go-build -gno-record-gcc-switches

What did you do?

package main

import (
	"fmt"
	"context"
	"time"
)

func main() {
	for i, _ := range make([]bool, 10) {
		ctx := context.Background()
		tCtx1, tCancel1 := context.WithTimeout(ctx, 1 * time.Nanosecond)
		tCtx2, tCancel2 := context.WithTimeout(ctx, 1 * time.Millisecond)

		select {
		case <- tCtx1.Done():
			tCancel2()
			fmt.Println(i, "tCtx1 timeout")
		case <- tCtx2.Done():
			tCancel1()
			fmt.Println(i, "tCtx2 timeout!!!")
		}
	}

	fmt.Println()

	for i, _ := range make([]bool, 10) {
		timer1 := time.NewTimer(1 * time.Nanosecond)
		timer2 := time.NewTimer(2 * time.Nanosecond)

		select {
		case <- timer1.C:
			timer2.Stop()
			fmt.Println(i, "timer1 timeout")
		case <- timer2.C:
			timer1.Stop()
			fmt.Println(i, "timer2 timeout!!!")
		}
	}
}

What did you expect to see?

0 tCtx1 timeout
1 tCtx1 timeout
2 tCtx1 timeout
3 tCtx1 timeout
4 tCtx1 timeout
5 tCtx1 timeout
6 tCtx1 timeout
7 tCtx1 timeout
8 tCtx1 timeout
9 tCtx1 timeout

0 timer1 timeout
1 timer1 timeout
2 timer1 timeout
3 timer1 timeout
4 timer1 timeout
5 timer1 timeout
6 timer1 timeout
7 timer1 timeout
8 timer1 timeout
9 timer1 timeout

What did you see instead?

0 tCtx1 timeout
1 tCtx2 timeout!!!
2 tCtx1 timeout
3 tCtx2 timeout!!!
4 tCtx2 timeout!!!
5 tCtx2 timeout!!!
6 tCtx2 timeout!!!
7 tCtx2 timeout!!!
8 tCtx2 timeout!!!
9 tCtx2 timeout!!!

0 timer1 timeout
1 timer1 timeout
2 timer1 timeout
3 timer1 timeout
4 timer1 timeout
5 timer1 timeout
6 timer1 timeout
7 timer1 timeout
8 timer1 timeout
9 timer1 timeout

[bcmills]

This may be an artifact of Windows timer resolution or other timer flakiness (see #8687, #44343, #29485, #28255, and possibly others) — it is possible that the time.NewTimer behavior only seems more consistent because of some implementation detail in how the goroutines are scheduled once the timer actually fires.

CC @prattmic @ChrisHines @egonelbre @ianlancetaylor

[egonelbre]

Yes, this looks like a duplicate of #44343.

Effectively, time.Sleep, time.Ticker and time.Timer all have granularity of 15ms on Windows. This, means that the minimum sleep is ~15ms. If you change the code to:

tCtx1, tCancel1 := context.WithTimeout(ctx, 1*time.Nanosecond)
tCtx2, tCancel2 := context.WithTimeout(ctx, 20*time.Millisecond)

It does behave the same way, however, of course, it doesn't solve the underlying problem.

[vellotis]

Yes, seems like a duplicate of #44343. Actually, this behavior doesn't bother me so much anymore as I am aware of it now. This is just a development machine. The dev+prod use a Linux distro.

If you feel so, you may close this issue.

I played around on Win10 and actually 5*time.Millisecond and higher gives a consistent succeeding performance.

Just for reference. The following benchmark with 1.16:

package main

import (
        "context"
	"fmt"
	"time"

	"github.com/loov/hrtime"
)

func main() {
	b := hrtime.NewBenchmark(100000)
	for b.Next() {
		ctx := context.Background()
		tCtx1, tCancel1 := context.WithTimeout(ctx, 1 * time.Nanosecond)
		tCtx2, tCancel2 := context.WithTimeout(ctx, 5 * time.Millisecond)

		select {
		case <- tCtx1.Done():
			tCancel2()
		case <- tCtx2.Done():
			tCancel1()
		}
	}
	fmt.Println(b.Histogram(10))
}

On Win10:

          avg 1.01ms;  min 3.3µs;  p50 1ms;  max 5.17ms;
          p90 1.1ms;  p99 2ms;  p999 2.12ms;  p9999 2.38ms;
              3.3µs [  264]
              500µs [47324] █████████████████████████████████████▌
                1ms [50340] ████████████████████████████████████████
              1.5ms [  907] ▌
                2ms [ 1161] ▌
              2.5ms [    1]
                3ms [    1]
              3.5ms [    1]
                4ms [    0]
              4.5ms+[    1]

On Alpine 9.2.0 (Linux 4.19.121-linuxkit x86_64) @ Docker:

          avg 1.39µs;  min 600ns;  p50 800ns;  max 265µs;
          p90 1.5µs;  p99 15.4µs;  p999 25.7µs;  p9999 153µs;
              600ns [97086] ████████████████████████████████████████
                5µs [  573]
               10µs [ 1003]
               15µs [ 1027]
               20µs [  204]
               25µs [   49]
               30µs [    9]
               35µs [    6]
               40µs [    8]
               45µs+[   35]

These results differ from the ones of #44343.

[bcmills]

Duplicate of #44343