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.

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

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

Closed
vellotis opened this issue Feb 25, 2021 · 4 comments
Closed
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows
Milestone

Comments

@vellotis
Copy link

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

bcmills commented Feb 25, 2021

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

@bcmills bcmills changed the title The performance of time.WithTimeout/time.WithDeadline is unbearably inconsistent context: WithTimeout scheduling is less deterministic than time.Timer on Windows Feb 25, 2021
@bcmills bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows labels Feb 25, 2021
@bcmills bcmills added this to the Backlog milestone Feb 25, 2021
@egonelbre
Copy link
Contributor

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

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

bcmills commented Feb 25, 2021

Duplicate of #44343

@bcmills bcmills marked this as a duplicate of #44343 Feb 25, 2021
@bcmills bcmills closed this as completed Feb 25, 2021
@golang golang locked and limited conversation to collaborators Feb 25, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows
Projects
None yet
Development

No branches or pull requests

4 participants