time: macOS monotonic time paused during sleep

[Plasmatium]

Go version

go version go1.22.1 darwin/amd64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='amd64'
GOBIN=''


GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''


GONOSUMDB=''
GOOS='darwin'

GOPRIVATE=''
GOPROXY='https://goproxy.cn,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.22.1'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/2x/l_3w120j35sgp9mpf4zlcjb40000gr/T/go-build2833465807=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

The issue happens in both go run main.go and vscode debug mode, on my macbook.
The code is running as expected on a Linux server.
Maybe this is an OS bug
No unsafe code.

Two variables:
expiresAt: a time.Time variable that stores the token when to expire, created like time.Now().After(expiresIn)
now: a time.Time variable that stores token checking time.

Then I use now.Before(expiresAt) to decide if I should renew the token.

What did you see happen?

now is after expiresAt, means token already expired, but now.Before(expiresAt) returns true. Below is a screenshot in vscode debug console:

Both now and expiresAt are created in the same process, and hasMonotonic bit is set to 1. So they just compare by ext:

time.Time defines here:

go/src/time/time.go

Lines 135 to 156 in d6c972a

	type Time struct {
	// wall and ext encode the wall time seconds, wall time nanoseconds,
	// and optional monotonic clock reading in nanoseconds.
	//
	// From high to low bit position, wall encodes a 1-bit flag (hasMonotonic),
	// a 33-bit seconds field, and a 30-bit wall time nanoseconds field.
	// The nanoseconds field is in the range [0, 999999999].
	// If the hasMonotonic bit is 0, then the 33-bit field must be zero
	// and the full signed 64-bit wall seconds since Jan 1 year 1 is stored in ext.
	// If the hasMonotonic bit is 1, then the 33-bit field holds a 33-bit
	// unsigned wall seconds since Jan 1 year 1885, and ext holds a
	// signed 64-bit monotonic clock reading, nanoseconds since process start.
	wall uint64
	ext int64
	// loc specifies the Location that should be used to
	// determine the minute, hour, month, day, and year
	// that correspond to this Time.
	// The nil location means UTC.
	// All UTC times are represented with loc==nil, never loc==&utcLoc.
	loc *Location
	}

Time.Before defines here:

go/src/time/time.go

Lines 265 to 273 in d6c972a

	// Before reports whether the time instant t is before u.
	func (t Time) Before(u Time) bool {
	if t.wall&u.wall&hasMonotonic != 0 {
	return t.ext < u.ext
	}
	ts := t.sec()
	us := u.sec()
	return ts < us || ts == us && t.nsec() < u.nsec()
	}

From the screenshot we can see there is a monotonic clock rollback issue, the m printed is not as expected. now is after expiresAt, but its m is smaller. This is a breakpoint hit in debug mode(after I send an API call), two variables surely created in the same process.

The issue is not always happen, unless I close the screen and a night passed.
Seems that while the computer sleep and awake, it will reset the monotonic clock to zero.

I wrote some code to reproduce quickly, but failed. The monotonic clock only stopped, but not reset, while the computer sleep for two hours when I go out for a launch.

"Monotonic clock may stop" is mentioned here in doc monotonic clock, but seems like it won't rollback (if it can, it's not monotonic)

The failed reproduce code is written as here in playground

And the output:

We can see the monotonic clock is only just stopped, but not reset (no rollback). I'll keep testing to let it pass a whole night to see if it could be reproduced.

Besides, more info:
The value of monotonic clock (stored as Time.ext) eventually comes from here [nanotime1] on mac os:

go/src/runtime/sys_darwin.go

Lines 332 to 350 in d6c972a

	func nanotime1() int64 {
	var r struct {
	t int64 // raw timer
	numer, denom uint32 // conversion factors. nanoseconds = t * numer / denom.
	}
	libcCall(unsafe.Pointer(abi.FuncPCABI0(nanotime_trampoline)), unsafe.Pointer(&r))
	// Note: Apple seems unconcerned about overflow here. See
	// https://developer.apple.com/library/content/qa/qa1398/_index.html
	// Note also, numer == denom == 1 is common.
	t := r.t
	if r.numer != 1 {
	t *= int64(r.numer)
	}
	if r.denom != 1 {
	t /= int64(r.denom)
	}
	return t
	}
	func nanotime_trampoline()

What did you expect to see?

I expect to see now.Before(expiresAt) should return false, then token can renew as expected.

[seankhliao]

related / dup of #35012 ?

[ianlancetaylor]

The time value comes from a call to mach_absolute_time. If that returns a value that sometimes resets to zero, that sounds like an operating system bug. If you are able to repeat the problem, perhaps you could modify nanotime1 to report whether nanotime_trampoline returns an r.t value of 0. That would point to the operating system as the problem, in which case it's not clear what Go can do.

This sounds a bit like libuv/libuv#2891. What version of Darwin are you running?

[Plasmatium]

The time value comes from a call to mach_absolute_time. If that returns a value that sometimes resets to zero, that sounds like an operating system bug. If you are able to repeat the problem, perhaps you could modify nanotime1 to report whether nanotime_trampoline returns an r.t value of 0. That would point to the operating system as the problem, in which case it's not clear what Go can do.

This sounds a bit like libuv/libuv#2891. What version of Darwin are you running?

14.4.1

I've tested with my friend and found that using simple code as this playground can't reproduce the issue. But this issue can be reproduced using our service code.

I'm going to write a simple gin service to try to reproduce this, and print mach_absolute_time

[Plasmatium]

Seems to be related to this issue: libuv/libuv#2891 as @ianlancetaylor mentioned

I write another simple code for reproducing this:

package main

/*
#cgo LDFLAGS: -framework CoreFoundation -framework IOKit
#include <mach/mach_time.h>

uint64_t mach_absolute_time_wrapper() {
    return mach_absolute_time();
}
*/
import "C"
import (
	"time"

	"github.com/gin-gonic/gin"
)

var expiresAt = time.Now().Add(time.Hour * 3)

func machAbsoluteNano() uint64 {
	return uint64(C.mach_absolute_time_wrapper())
}

func toDur(nano uint64) time.Duration {
	return time.Duration(nano) * time.Nanosecond
}

func main() {
	r := gin.Default()
	r.GET("/time", handler)
	r.Run(":8080")
}

func handler(c *gin.Context) {
	now := time.Now()
	isBefore := now.Before(expiresAt)
	uptime := machAbsoluteNano()
	c.JSON(200, gin.H{
		"isBefore":             isBefore,
		"mach_absolute_time()": uptime,
		"now":                  now.String(),
		"expiresAt":            expiresAt.String(),
		"uptimeDuration":       toDur(uptime).String(),
	})
}

output:

$ curl localhost:8080/time -s | jq
{
  "expiresAt": "2024-04-19 17:14:28.654548 +0800 CST m=+10800.003901671",
  "isBefore": true,
  "mach_absolute_time()": 76197193801457,
  "now": "2024-04-19 14:15:36.137978 +0800 CST m=+67.486527117",
  "uptimeDuration": "21h9m57.193801457s"
}

I'll check this next morning (about 18~20hrs later)

[Plasmatium]

Maybe there is no such clock reset things. It just stopped while sleep. For example, var expiresAt = time.Now().Add(time.Hour * 3) means expiresAt: m=+10800, and now: m=+67. If I let the computer sleep imediatly in 1 sec, then next day, new now is surely not before expiresAt, but due to the monotonic clock stopped, m of now may still equal to +67, which is smaller then +10800, cause now is before expires (67 < 10800).

Although the stopping of a monotonic clock does not destroy its monotonicity, it may introduce bugs in this case.

So in macos(or other OS that may stop the monotonic clock), we may using raw mach_absolute_time() to avoid this bug.

To make this reproducing more clearly, I'll modify expiresAt to tomorrow 6 a.m UTC+8 (about 15hrs later), and some data:

$ curl localhost:8080/time -s | jq
{
  "expiresAt": "2024-04-20 06:00:23.307705 +0800 CST m=+51720.003813063",
  "isBefore": true,
  "mach_absolute_time()": 80009874232411,
  "now": "2024-04-19 15:38:26.38051 +0800 CST m=+3.076554055",
  "uptimeDuration": "22h13m29.874232411s"
}

Next morning after 8:00 am, I'll fire another curl, and expect that due to monotonic clock stopping during sleep, new now's m will smaller then expiresAt m=+51720.003813063

[Plasmatium]

The key point is, if you are going to sleep 4hrs, the value time.Now().Add(someInterval), it's monotonic clock (the m value) should also minus 4hrs:
Before sleep, expiresAt monotonic clock is 10hrs
After sleep 4hrs, expiresAt monotonic clock should minus 4hrs, to 6hrs, because after sleep, all generated Time struct's monotonic clocks are lost 4hrs for ever.

This issue may impact App written in go, like created by https://github.com/wailsapp/wails

[Plasmatium]

As mentioned in this issue: #23178, this is an expected behavior.
https://pkg.go.dev/time#hdr-Monotonic_Clocks

On some systems the monotonic clock will stop if the computer goes to sleep. On such a system, t.Sub(u) may not accurately reflect the actual time that passed between t and u.

For my case, I can use t.Round(0) to remove monotonic clock, and make all things happy.

Maybe I could add some comment to t.Sub, t.Add, t.Before, t.After, to warn people about this trap

[Plasmatium]

Added some notes. PR here: #66922

[gopherbot]

Change https://go.dev/cl/580515 mentions this issue: time: add notes about monotonic time paused