time: time.After and time.Sleep return early on windows/amd64 #45582
Comments
mknyszek
changed the title
mknyszek
added
NeedsInvestigation
|
Thanks for the detailed issue and the small reproducer! Always greatly appreciated. |
|
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): It seems this problem is highly environment-dependent and probably needs a docker file for a reliable reproduction. Yours, |
|
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 /timetestThe 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 |
|
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.) |
|
@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 |
What version of Go are you using (
go version)?OS: Microsoft Windows Server 2019 Standard
Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (
go env)?go envOutputWhat did you do?
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)
Next iteration 59.9894804s left until the start of the next minute, but ended earlier (next cycle start at 15:30:59.9997131)
Next iteration 59.9897221s left until the start of the next minute, but ended earlier (next cycle start at 15:31:59.9993215)
... Skipped
Next iteration 59.9903326s left until the start of the next minute, CORRECT!!! (next cycle start at 15:41:00.000753)
Next iteration 59.9886968s left until the start of the next minute, CORRECT!!! (next cycle start at 15:42:00.0000637)
Next iteration 59.9891146s left until the start of the next minute, but ended earlier (next cycle start at 15:42:59.9990432)
On Linux all good (but linux is not so heavily loaded)
The text was updated successfully, but these errors were encountered: