time: time.After and time.Sleep return early on windows/amd64

[sitnikovv]

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

OS: Microsoft Windows Server 2019 Standard

$ go version
go version go1.16.3 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=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\xxx\AppData\Local\go-build
set GOENV=C:\Users\xxx\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=d:\gopath\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=d:\gopath
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=c:\go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.16.3
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 -fmessage-length=0 -fdebug-prefix-map=C:\Users\xxx\AppData\Local\Temp\2\go-build1340947938=/tmp/go-build -gno-record-gcc-switches

What did you do?

package main

import (
	"fmt"
	"time"
)

func TruncateMinute(inputTime time.Time, minute int) time.Time {
	return inputTime.Truncate(time.Duration(minute) * time.Minute)
}

func main() {
	for {
		tickTime := time.Now()
		fmt.Printf("\ncron_tick: %v\n", tickTime)

		time.Sleep(10 * time.Millisecond)

		now := time.Now()
		nextTick := TruncateMinute(now.Add(time.Minute), 1)
		waitTick := nextTick.Sub(now)
		fmt.Printf("cron_now: %v\n", now)
		fmt.Printf("cron_next: %v\n", nextTick)
		fmt.Printf("cron_wait: %v\n", waitTick)
		//time.Sleep(waitTick)
		select {
		case <-time.After(waitTick):
		}
	}

}

What did you expect to see?

I expected time.After not to fire ahead of time

What did you see instead?

Start, there are 17.3107307s left until the start of the next minute, but ended earlier (next cycle start at 15:29:59.9998877)

cron_tick: 2021-04-15 15:29:42.6426691 +0300 MSK m=+0.003286301
cron_now: 2021-04-15 15:29:42.6892693 +0300 MSK m=+0.049887501
cron_next: 2021-04-15 15:30:00 +0300 MSK
cron_wait: 17.3107307s

Next iteration 59.9894804s left until the start of the next minute, but ended earlier (next cycle start at 15:30:59.9997131)

cron_tick: 2021-04-15 15:29:59.9998877 +0300 MSK m=+17.360879901
cron_now: 2021-04-15 15:30:00.0105196 +0300 MSK m=+17.371512001
cron_next: 2021-04-15 15:31:00 +0300 MSK
cron_wait: 59.9894804s

Next iteration 59.9897221s left until the start of the next minute, but ended earlier (next cycle start at 15:31:59.9993215)

cron_tick: 2021-04-15 15:30:59.9997131 +0300 MSK m=+77.361995801
cron_now: 2021-04-15 15:31:00.0102779 +0300 MSK m=+77.372560801
cron_next: 2021-04-15 15:32:00 +0300 MSK
cron_wait: 59.9897221s

... Skipped

Next iteration 59.9903326s left until the start of the next minute, CORRECT!!! (next cycle start at 15:41:00.000753)

cron_tick: 2021-04-15 15:39:59.999119 +0300 MSK m=+617.373498701
cron_now: 2021-04-15 15:40:00.0096674 +0300 MSK m=+617.384047301
cron_next: 2021-04-15 15:41:00 +0300 MSK
cron_wait: 59.9903326s

Next iteration 59.9886968s left until the start of the next minute, CORRECT!!! (next cycle start at 15:42:00.0000637)

cron_tick: 2021-04-15 15:41:00.0007533 +0300 MSK m=+677.376445001
cron_now: 2021-04-15 15:41:00.0113032 +0300 MSK m=+677.386995101
cron_next: 2021-04-15 15:42:00 +0300 MSK
cron_wait: 59.9886968s

Next iteration 59.9891146s left until the start of the next minute, but ended earlier (next cycle start at 15:42:59.9990432)

cron_tick: 2021-04-15 15:42:00.0000637 +0300 MSK m=+737.377059301
cron_now: 2021-04-15 15:42:00.0108854 +0300 MSK m=+737.387881301
cron_next: 2021-04-15 15:43:00 +0300 MSK
cron_wait: 59.9891146s

cron_tick: 2021-04-15 15:42:59.9990432 +0300 MSK m=+797.377335701
cron_now: 2021-04-15 15:43:00.0104573 +0300 MSK m=+797.388750001
cron_next: 2021-04-15 15:44:00 +0300 MSK
cron_wait: 59.9895427s

On Linux all good (but linux is not so heavily loaded)

[mknyszek]

Thanks for the detailed issue and the small reproducer! Always greatly appreciated.

CC @ianlancetaylor @prattmic @ChrisHines

[networkimprov]

cc @zx2c4 @alexbrainman @mattn

[andreybokhanko]

FWIW, I can't reproduce this issue on my two Windows x86-64 machines (one is Windows 10 Enterprise, another is Windows 10 Pro), using go1.16.5 built with CGO and go1.16.3 that I built myself (without CGO, as I don't have a C compiler on my machine):

cron_tick: 2021-06-08 18:07:00.003787 +0300 MSK m=+4014.475411501
cron_now: 2021-06-08 18:07:00.0210998 +0300 MSK m=+4014.492724301
cron_next: 2021-06-08 18:08:00 +0300 MSK
cron_wait: 59.9789002s

cron_tick: 2021-06-08 18:08:00.0116271 +0300 MSK m=+4074.483257601
cron_now: 2021-06-08 18:08:00.0289214 +0300 MSK m=+4074.500551901
cron_next: 2021-06-08 18:09:00 +0300 MSK
cron_wait: 59.9710786s

cron_tick: 2021-06-08 18:09:00.0098472 +0300 MSK m=+4134.481483701
cron_now: 2021-06-08 18:09:00.0266484 +0300 MSK m=+4134.498284901
cron_next: 2021-06-08 18:10:00 +0300 MSK
cron_wait: 59.9733516s

cron_tick: 2021-06-08 18:10:00.003472 +0300 MSK m=+4194.475114501
cron_now: 2021-06-08 18:10:00.0148765 +0300 MSK m=+4194.486519001
cron_next: 2021-06-08 18:11:00 +0300 MSK
cron_wait: 59.9851235s

cron_tick: 2021-06-08 18:11:00.0156636 +0300 MSK m=+4254.487312101
cron_now: 2021-06-08 18:11:00.0350066 +0300 MSK m=+4254.506655101
cron_next: 2021-06-08 18:12:00 +0300 MSK
cron_wait: 59.9649934s

cron_tick: 2021-06-08 18:12:00.0178345 +0300 MSK m=+4314.489489001
cron_now: 2021-06-08 18:12:00.0350977 +0300 MSK m=+4314.506752201
cron_next: 2021-06-08 18:13:00 +0300 MSK
cron_wait: 59.9649023s

cron_tick: 2021-06-08 18:13:00.0176599 +0300 MSK m=+4374.489320401
cron_now: 2021-06-08 18:13:00.0342954 +0300 MSK m=+4374.505955901
cron_next: 2021-06-08 18:14:00 +0300 MSK
cron_wait: 59.9657046s

...

It seems this problem is highly environment-dependent and probably needs a docker file for a reliable reproduction.

Yours,
Andrey
===
Advanced Software Technology Lab
Huawei

[JohnRoesler]

Hey all, I am able to reproduce this with a Dockerfile building the code snippet posted in the original issue:

FROM golang:1.17.0-buster
WORKDIR /app

COPY go.* ./
RUN go mod download

COPY *.go ./

RUN go build -o /timetest
ENTRYPOINT /timetest

The results show that on just my third tick it happened slightly early causing the message to appear twice for the 16:48 minute

docker run -it timetest:v0.0.1

cron_tick: 2021-08-23 16:46:54.691913655 +0000 UTC m=+0.000097728
cron_now: 2021-08-23 16:46:54.703024674 +0000 UTC m=+0.011208744
cron_next: 2021-08-23 16:47:00 +0000 UTC
cron_wait: 5.296975326s

cron_tick: 2021-08-23 16:47:00.000868299 +0000 UTC m=+5.309052386
cron_now: 2021-08-23 16:47:00.011140129 +0000 UTC m=+5.319324201
cron_next: 2021-08-23 16:48:00 +0000 UTC
cron_wait: 59.988859871s

cron_tick: 2021-08-23 16:47:59.978902457 +0000 UTC m=+65.327759820
cron_now: 2021-08-23 16:47:59.989480843 +0000 UTC m=+65.338338206
cron_next: 2021-08-23 16:48:00 +0000 UTC
cron_wait: 10.519157ms

cron_tick: 2021-08-23 16:48:00.000928234 +0000 UTC m=+65.349785597
cron_now: 2021-08-23 16:48:00.011381157 +0000 UTC m=+65.360238520
cron_next: 2021-08-23 16:49:00 +0000 UTC
cron_wait: 59.988618843s

[antong]

I might be wrong, but if you compare the monotonic times, it looks like it actually does not fire early (consider also printing the diff between cron_tick and previous cron_now, which would make this clear.)

[JohnRoesler]

@antong I see that now with the monotonic times that it is NOT in fact returning early. The issue does appear to be a slightly out of sync issue between the monotonic and wall clocks. Reading through #27090 this appears to be due to the separate calls to get the two times from the host.

I put together a work around in the select statement for the time.After that just runs a for loop until the wall clock time is greater or equal to the expected wall clock time:

package main

import (
	"fmt"
	"time"
)

func TruncateMinute(inputTime time.Time, minute int) time.Time {
	return inputTime.Truncate(time.Duration(minute) * time.Minute)
}

func main() {

	for {
		tickTime := time.Now()
		fmt.Printf("\ncron_tick: %v\n", tickTime)

		time.Sleep(10 * time.Millisecond)

		now := time.Now()
		nextTick := TruncateMinute(now.Add(time.Minute), 1)
		waitTick := nextTick.Sub(now)
		fmt.Printf("now: %v\n", now)
		fmt.Printf("next: %v\n", nextTick)
		fmt.Printf("wait: %v\n", waitTick)

		select {
		case <-time.After(waitTick):
			for {
				if time.Now().Unix() >= nextTick.Unix() {
					break
				}
			}
		}
	}
}

I would suggest this issue could be closed in favor of #27090