为什么 Go 的 time.Now().UnixNano() 返回的结果较小？

Question

我使用 time.Now().UnixNano() 来计算 rpc 的时间，但我发现第二次调用 time.Now().UnixNano() 返回的时间戳比第一次调用更小。这段代码属于rpc客户端。我同时执行了数万次，有时它会出现一次。

start := time.Now().UnixNano()
v := ck.Get(key)
end := time.Now().UnixNano()
if start > end {
   fmt.Printf("TimeReverseErr found: callTime %v > returnTime %v\n", start, end)
}

以下是输出：

... found: callTime 1667161706348148000 > returnTime 1667161706304057000
... found: callTime 1667161706365079000 > returnTime 1667161706319597000

操作系统：macOS Monterey 12.6
Go：go1.18 darwin/amd64

完整代码：

// in RPC Client
func Get(cfg *config, ck *Clerk, key string, log *OpLog, cli int) string {
   start := time.Now().UnixNano()
   v := ck.Get(key)
   end := time.Now().UnixNano()
   if start > end {
      fmt.Printf("TimeReverseErr found: callTime %v > returnTime %v", start, end)
   }
   cfg.op()
   if log != nil {
      log.Append(porcupine.Operation{
         Input:    models.KvInput{Op: 0, Key: key},
         Output:   models.KvOutput{Value: v},
         Call:     start,
         Return:   end,
         ClientId: cli,
      })
   }

   return v
}

我已经尝试了很多次，这个问题仍然存在。

Answer 1

time.Now().UnixNano()是一个挂钟读数，它不是一个单调的时钟读数。

\n

\n

时间：单调时钟

\n

操作系统提供了 \xe2\x80\x9c 挂钟、\xe2\x80\x9d 和 \xe2\x80\x9c 单调时钟，其中 \xe2\x80\x9d 会因时钟同步而发生变化，而 \xe2\x80\x9d 则不会。一般规则是，挂钟用于报时，单调钟用于测量时间。在此包中，time.Now 返回的 Time 包含挂钟读数和单调时钟读数，而不是拆分 API；后来的报时操作使用挂钟读数，但后来的时间测量操作，特别是比较和减法，使用单调时钟读数。

\n

例如，此代码始终计算大约 20 毫秒的正经过时间，即使挂钟在计时操作期间发生更改：

\n

start := time.Now()\n... operation that takes 20 milliseconds ...\nt := time.Now()\nelapsed := t.Sub(start)\n

\n

\n\n

改写您的代码以使用time.Now()单调时钟。例如，

\n

package main\n\nimport (\n    "fmt"\n    "time"\n)\n\nfunc Get(key string) string { return "value" }\n\nfunc main() {\n    key := "key"\n\n    start := time.Now()\n    v := Get(key)\n    end := time.Now()\n    since := end.Sub(start)\n\n    fmt.Println(start)\n    fmt.Println(end)\n    fmt.Println(since)\n    if since < 0 {\n        fmt.Println("start > end")\n    }\n\n    _ = v\n}\n

\n

m=+0.000018015是单调时钟值。

\n

2022-10-31 00:38:30.415473095 -0400 EDT m=+0.000018015\n2022-10-31 00:38:30.415473159 -0400 EDT m=+0.000018073\n58ns\n

\n