time: Sub is inaccurate after computer has slept

[petemoore]

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]

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]

Now it all makes sense, many thanks!

[petemoore]

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.

[ALTree]

cc @rsc

[mvdan]

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.

[gopherbot]

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