go: runtime: time.Sleep problem on Windows 10, but not Windows 7 or Linux

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

go version go1.20.5 windows/amd64 - “new” go version go1.15.13 windows/amd64 - “old”

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (`go env`)?

windows_amd64 - Windows 10 Pro, 22H2, Build 19045.2965 windows_amd64 - Windows 7 Ultimate, 6.1.7601, Service Pack 1, Build 7601

What did you do?

package main

import (
	"fmt"
	"time"
)

func main() {
	fmt.Println()
	fmt.Println("Time Resolution")
	for i := 0; i < 10; i++ {
		fmt.Printf("    %v\n", timeDiff())
	}

	fmt.Println()
	fmt.Println("Sleep Resolution")
	time.Sleep(1) // sync with the sleep timer
	for i := 0; i < 10; i++ {
		fmt.Printf("    %v\n", sleepDiff())
	}
}

func timeDiff() time.Duration {
	t0 := time.Now()
	for {
		t := time.Now()
		if t != t0 {
			return t.Sub(t0)
		}
	}
}

func sleepDiff() time.Duration {
	t0 := time.Now()
	time.Sleep(1)
	return time.Now().Sub(t0)
}

What did you expect to see?

Results using Go v1.15.13 or v1.20.5 code on Windows 7. Time Resolution is fine. Sleep Resolution is fine.

Time Resolution
    1.0001ms
    1ms
    1.0001ms
    1ms
    1.0001ms
    1ms
    1.0001ms
    1.0001ms
    1ms
    1.0001ms

Sleep Resolution
    1ms
    1.0001ms
    1.0001ms
    1ms
    1.0001ms
    1ms
    1.0001ms
    1ms
    1.0001ms
    1.0001ms

What did you see instead?

Results using Go v1.20.5 code on Windows 10. Time Resolution is fine. Sleep Resolution is bad. It should be ~1ms.

Time Resolution
    509.5µs
    555.1µs
    587.7µs
    95.9µs
    585.7µs
    585.4µs
    596.7µs
    514.4µs
    514.4µs
    514.1µs

Sleep Resolution
    15.2307ms
    34.8µs
    13.9486ms
    14.8512ms
    15.1862ms
    15.0722ms
    15.7843ms
    15.6718ms
    898.4µs
    14.525ms

Results using Go v1.15.13 code on Windows 10. Time Resolution is ok. Sleep Resolution is ok. Neither are as good as when run on Windows 7, but they are certainly usable.

Time Resolution
    1.0394ms
    1.0505ms
    918.6µs
    1.022ms
    997.7µs
    1.0016ms
    1.0788ms
    986.7µs
    1.0057ms
    993.9µs

Sleep Resolution
    1.0853ms
    1.1475ms
    1.1202ms
    995.8µs
    1.211ms
    1.2033ms
    1.2386ms
    1.2209ms
    1.0501ms
    1.1822ms

=== Comments

Comments:

A problem I was having with a program I was working on led me to this issue. So yes, it makes a difference in the real world.

I don’t have a Windows 11 PC. It would be interesting to see if it has the problem or not.

The “new” code was built on the Windows 10 PC. The “old” code was build on the Windows 7 PC.

Both Windows PC clocks were running at 1ms due to other software on them. This was verified using TimerTool.exe. But this is moot, since the very first Sleep should have caused Go’s auto-clock-switch to force it to 1ms and keep it there till 50ms after the last Sleep.

The Windows 10 PC is about 5 times faster than the much older Windows 7 PC. Yet the results from the older PC are much “cleaner” (less latency error).

The “new” (I didn’t try old) code was fine on both a Linux server and Raspberry Pi 4.

About this issue

Original URL
State: closed
Created a year ago
Comments: 27 (12 by maintainers)

Most upvoted comments

is this #44343 ?

seankhliao on Jun 27, 2023

@ChrisHines

No response. What’s the procedure for a proposal?

Thanks.

johnrs on Jul 13, 2023

I agree this looks like a duplicate of #44343 to me.

@johnrs If you haven’t seen them yet, these two comments from that issue should give enough information to understand what change caused the regression starting with Go 1.16 and a lot of detail about how the runtime timers are interacting with Windows at the moment:

I don’t understand one of your points from above, though:

I believe it should be stated as the Sleep delay will always be greater than or equal to what it is called with minus one system clock tick.

What I don’t understand is when you are seeing sleeps shorter than the requested duration. I invested quite a lot of time understanding how the runtime timers code works a few years ago and I can’t think of any way for that to actually happen. As I noted in https://github.com/golang/go/issues/44343#issuecomment-781065368 I’ve actually seen the linux kernal wakeup earlier than Go asked it to, but the Go runtime knew it was too early and just went to sleep again.

I don’t see any examples of “short sleeps” in the example you gave in the top post. All the calls to time.Sleep(1) in the code request a 1ns sleep. So right away the only possible shorter value Go could report is 0ns, because time.Duration has a 1ns resolution. The shortest wakeup time in the shown results is 34.8µs, which is certainly >= 1ns.

If I understand right, you are suggesting that sometimes a call like time.Sleep(20 * time.Millisecond) will return and time.Since(start) would report a time less than 20ms. I don’t think that will ever happen in normal operation. Here’s a very simple explanation of how it works:

A call to time.Sleep queues a runtime timer that records the target wakeup time.
The runtime ensures there is a thread sleeping on an OS primitive until the soonest of all known timers.
When that thread wakes up the runtime pulls all expired timers from the timer queue and makes their goroutines runnable again.
If there are still unexpired timers a thread calculates the new soonest of them and sleeps until then.
etc.

That’s an extreme simplification, but it highlights the fact that time.Sleep should not return until the clock has advanced past its scheduled wake up time as calculated when the call was made.

ChrisHines on Jun 29, 2023

I suspect they are the same issue (especially given the Go version ranges). Could you elaborate on which of the symptoms are different? Thanks.

Also, if you’re so inclined, it should be straightforward to identify if it’s the same issue by trying https://github.com/golang/go/commit/8fdc79e18a9704185bd6471b592db1e8004bd993 and the commit before.

mknyszek on Jun 28, 2023