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

time: Sub is inaccurate after computer has slept #23178

Closed
petemoore opened this issue Dec 19, 2017 · 6 comments
Closed

time: Sub is inaccurate after computer has slept #23178

petemoore opened this issue Dec 19, 2017 · 6 comments
Labels
Documentation FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@petemoore
Copy link

petemoore commented Dec 19, 2017

Please answer these questions before submitting your issue. Thanks!

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

go version go1.9.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/pmoore/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.9.2/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.9.2/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/v9/mll6p_rj5h94dt_m5m8j0f9c0000gn/T/go-build287238210=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
$ sw_vers
ProductName:	Mac OS X
ProductVersion:	10.13.1
BuildVersion:	17B1003

What did you do?

I ran the following program, and then waited for my iMac sleep. I woke it up again.

$ cat main.go 
package main

import (
	"fmt"
	"time"
)

func main() {
	start := time.Now()
	for {
		time.Sleep(time.Second)
		end := time.Now()
		fmt.Printf("Start: %v, End: %v, Duration: %v\n", start, end, end.Sub(start))
	}
}
$ go run main.go 
....
....
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:06:22.691501 +0100 CET m=+153.190165077, Duration: 2m33.189775511s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:06:23.691737 +0100 CET m=+154.190447504, Duration: 2m34.190057938s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:06:24.691824 +0100 CET m=+155.190580407, Duration: 2m35.190190841s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:06:25.692191 +0100 CET m=+156.190990386, Duration: 2m36.19060082s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:06:26.692307 +0100 CET m=+157.191153372, Duration: 2m37.190763806s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:14:33.892169 +0100 CET m=+158.581754838, Duration: 2m38.581365272s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:14:34.893832 +0100 CET m=+159.583462000, Duration: 2m39.583072434s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:14:35.894375 +0100 CET m=+160.584051261, Duration: 2m40.583661695s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:14:36.895479 +0100 CET m=+161.585199077, Duration: 2m41.584809511s
Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:14:37.895651 +0100 CET m=+162.585417039, Duration: 2m42.585027473s

What did you expect to see?

I expected the log output for Duration to equal the difference between the timestamps logged for Start and End. For example, the last line is:

Start: 2017-12-19 14:03:49.50865 +0100 CET m=+0.000389566, End: 2017-12-19 14:14:37.895651 +0100 CET m=+162.585417039, Duration: 2m42.585027473s

If start is 14:03:49.5 and end is 14:14:37.9 then duration should be 10m48.4s not 2m42.6s.

Note, the 8 minute jump in end time from 14:06:26.7 to 14:14:33.9 was when the computer was sleeping.

What did you see instead?

The duration calculation seemed to match the amount of awake time between start and end time. Notice how when the end time jumps eight minutes (due to the computer being asleep), the duration only increments by around one second, as if no sleep had occurred.

@nussjustin
Copy link
Contributor

This is expected, see the documentation for the time package.

You can always remove the monotonic part from a time.Time:

The Time returned by time.Now contains a monotonic clock reading. If Time t has a monotonic clock reading, t.Add adds the same duration to both the wall clock and monotonic clock readings to compute the result. Because t.AddDate(y, m, d), t.Round(d), and t.Truncate(d) are wall time computations, they always strip any monotonic clock reading from their results. Because t.In, t.Local, and t.UTC are used for their effect on the interpretation of the wall time, they also strip any monotonic clock reading from their results. The canonical way to strip a monotonic clock reading is to use t = t.Round(0).

See also the issue for this: #12914

@petemoore
Copy link
Author

Now it all makes sense, many thanks!

@petemoore
Copy link
Author

I have one concern with this: the use of monotonic clocks is advocated to ensure that elapsed time is measured correctly, independent of changes made to system clocks. However, this falls down if the computer sleeps. It seems there is no safe way to measure the real elapsed time, since:

  1. If you use wall clock time, user changes to the system clock will skew results
  2. If you use monotonic time, any sleep time will skew results

Particularly with a lot of software running on laptops, the chance of 2) is probably higher than the chance of 1). And currently there is no third option that isn't skewed by sleep or system clock changes.

If a third option can't be implemented that solves the deficiencies of 1) and 2), I think it would be good for the docs to specifically call out that during computer sleep, the monotonic clock stops.

@petemoore petemoore reopened this Dec 20, 2017
@ALTree ALTree changed the title (time.Time).Sub(time.Time) inaccurate after computer has slept time: Sub is inaccurate after computer has slept Dec 20, 2017
@ALTree ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 20, 2017
@ALTree
Copy link
Member

ALTree commented Dec 20, 2017

cc @rsc

@mvdan
Copy link
Member

mvdan commented Dec 20, 2017

I think it is worth pointing out that 1 and 2 are problems of different magnitude. With 1, you could very easily have negative elapsed times. That would not only be confusing, but also easily break programs unless you took it into account.

But with 2, a user can only stop the clock, not move it back. In other words, it is impossible to have negative elapsed times - just smaller ones.

Not knowing much about monotonic times, I wonder - does any kernel or operating system keep track of sleep time as well as awake time? If it is possible with today's hardware at all.

@ianlancetaylor ianlancetaylor added Documentation NeedsFix The path to resolution is known, but the work has not been done. labels Mar 29, 2018
@ianlancetaylor ianlancetaylor added this to the Go1.11 milestone Mar 29, 2018
@gopherbot gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 29, 2018
@gopherbot
Copy link

Change https://golang.org/cl/103396 mentions this issue: time: document that going to sleep may stop the monotonic clock

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Documentation FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

6 participants