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: macOS monotonic time paused during sleep #66870

Open
Plasmatium opened this issue Apr 17, 2024 · 9 comments
Open

time: macOS monotonic time paused during sleep #66870

Plasmatium opened this issue Apr 17, 2024 · 9 comments
Labels
Documentation NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin

Comments

@Plasmatium
Copy link
Contributor

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:

IMG_6613

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:
image
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:

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.

@mauri870 mauri870 added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin labels Apr 17, 2024
@seankhliao
Copy link
Member

related / dup of #35012 ?

@seankhliao seankhliao changed the title Mac OS Monotonic time rollback time: macOS monotonic time paused/reset during sleep Apr 17, 2024
@ianlancetaylor
Copy link
Contributor

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?

@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 17, 2024
@Plasmatium
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

Plasmatium commented Apr 19, 2024

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
Copy link
Contributor Author

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

@seankhliao seankhliao changed the title time: macOS monotonic time paused/reset during sleep time: macOS monotonic time paused during sleep Apr 19, 2024
@seankhliao seankhliao added Documentation and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Apr 19, 2024
@Plasmatium
Copy link
Contributor Author

Added some notes. PR here: #66922

@gopherbot
Copy link

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

gopherbot pushed a commit that referenced this issue Apr 29, 2024
See #66870

Change-Id: I781265355a3dbd0d9538bc9dcafaa83b482ec3f8
GitHub-Last-Rev: 9d92f11
GitHub-Pull-Request: #66922
Reviewed-on: https://go-review.googlesource.com/c/go/+/580515
Reviewed-by: Ian Lance Taylor <iant@google.com>
Auto-Submit: Ian Lance Taylor <iant@google.com>
Reviewed-by: Joedian Reid <joedian@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Documentation NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin
Projects
None yet
Development

No branches or pull requests

6 participants
@ianlancetaylor @gopherbot @mauri870 @seankhliao @Plasmatium and others