time: time.After() seems to return early by 5 milliseconds sometimes.

[DavidVorick]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.7.1 linux/amd64

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

amd64
linux

Qubes -> Whonix (Debian based)

What did you do?

https://play.golang.org/p/YLOXGJrc92

What did you expect to see?

Locked the trylock
Lock failed, time passed: 500ms

What did you see instead?

Locked the trylock
Lock failed, time passed: 495ms

---

I've only been able to reproduce this on my machine, but time.After was returning 5 milliseconds early in a few contexts with similar code. Not a big deal for my project, but wanted to report that I was seeing unexpected things.

[DavidVorick]

go test -timeout=500s is sometimes returning after only 497 seconds. So it seems to be a similar problem. Are there two different timers being used? Perhaps hardware vs. software clocks? Maybe my machine is not synchronized with itself.

[bradfitz]

Yes, one is monotonic time and one is wall time.

Does this only happen in Qubes for you, which I believe is running your process under Xen?

[DavidVorick]

I've only seen it so far on Qubes, which indeed uses Xen. I also had several AppVMs running at once, which means that they were being switched out. I'm guessing that's the source of the discrepency.

[quentinmit]

5ms out of 500ms is a 1% error. I would be shocked if monotonic and wall time were that different over a half a second.

Do you have ntpd running in your VM? Or are you using Xen's clock syncing? What is the output of cat /sys/devices/system/clocksource/clocksource0/current_clocksource ?

[DavidVorick]

looks like xen is running as the clock source.

output is xen

[rsc]

This was caused by 86c976f which was done for #6007: the 500ms sleep is monotonic clock ms, and the measured 495ms is wall time ms.

The fact is that if your monotonic and wall clocks don't line up, you're going to be in for trouble one way or another. It used to be one way. Now it's another. I wish we hadn't changed it, but not enough to change it back.

[rsc]

FWIW, I expect this program to work as expected now if built with Go's master branch, after the fix for #12914 that landed today. Both the time.After and the time.Now().Sub(start) shold be using the same clock, and they should both report 500ms. If you were to subtract t.UnixNano() or something like that, you'd still see 495ms, but I expect that is an accurate reflection of xen turning your clock back.