为什么 time.Now().UnixNano() 在 IO 操作后返回相同的结果？答案

【问题标题】：Why does time.Now().UnixNano() returns the same result after an IO operation?为什么 time.Now().UnixNano() 在 IO 操作后返回相同的结果？
【发布时间】：2019-12-08 15:36:37
【问题描述】：

我使用time.Now().UnixNano() 来计算我的部分代码的执行时间，但我发现了一件有趣的事情。 IO 操作后经过的时间有时为零！它有什么问题？

代码在 Go 1.11 中运行，并使用标准库 "time"。 Redis 库是"github.com/mediocregopher/radix.v2/redis"。 redis服务器版本为3.2。我正在使用 VSCode 编辑器在 Windows 上运行它。

isGatherTimeStat = false
if rand.Intn(100) < globalConfig.TimeStatProbability { // Here I set TimeStatProbability 100
    isGatherTimeStat = true
}
if isGatherTimeStat {
    timestampNano = time.Now()
}
globalLogger.Info("time %d", time.Now().UnixNano())
resp := t.redisConn.Cmd("llen", "log_system")
globalLogger.Info("time %d", time.Now().UnixNano())
if isGatherTimeStat {
    currentTimeStat.time = time.Since(timestampNano).Nanoseconds()
    currentTimeStat.name = "redis_llen"
    globalLogger.Info("redis_llen time sub == %d", currentTimeStat.time)
    select {
    case t.chTimeStat <- currentTimeStat:
    default:
    }
}

这里有一些日志：

[INFO ][2019-07-31][14:47:53] time 1564555673269444200
[INFO ][2019-07-31][14:47:53] time 1564555673269444200
[INFO ][2019-07-31][14:47:53] redis_llen time sub == 0
[INFO ][2019-07-31][14:47:58] time 1564555678267691700
[INFO ][2019-07-31][14:47:58] time 1564555678270689300
[INFO ][2019-07-31][14:47:58] redis_llen time sub == 2997600
[INFO ][2019-07-31][14:48:03] time 1564555683268195600
[INFO ][2019-07-31][14:48:03] time 1564555683268195600
[INFO ][2019-07-31][14:48:03] redis_llen time sub == 0
[INFO ][2019-07-31][14:48:08] time 1564555688267631100
[INFO ][2019-07-31][14:48:08] time 1564555688267631100
[INFO ][2019-07-31][14:48:08] redis_llen time sub == 0

【问题讨论】：

您在哪个硬件架构上运行？
你是在 Windows 上运行这个吗？
@icza 是的，它在 Windows 上运行。
@icza 实际上在 VSCode 编辑器中。
您的代码没有问题。在 Windows 上，时间分辨率通常高于 1 毫秒。这意味着如果您在一毫秒内两次查询实际时间，您通常会得到相同的值。您的操作有时会产生t = 2997600ns = 0.3μs，这可以解释这一点。归咎于 Windows。

标签： windows go time

【解决方案1】：

您的代码没有问题。在 Windows 上，系统时间通常每 10-15 毫秒左右才更新一次，这意味着如果您在此期间两次查询当前时间，则得到相同的值。

您的操作有时会产生t = 2997600ns = 3ms，这可以解释这一点。归咎于 Windows。

相关问题：

How precise is Go's time, really?

How to determine the current Windows timer resolution?

Measuring time differences using System.currentTimeMillis()

【讨论】：

系统时间精度为100ns，但仅由系统定时器中断每15ms左右更新一次。定时器分辨率可以降低到毫秒或更短，但这会影响调度程序并导致功耗显着增加。如果我们需要测量精确的间隔，而不是记录系统时间戳，我们会使用系统性能计数器，即无论 Go 以何种方式公开 WINAPI QueryPerformanceCounter。

【解决方案2】：

Windows 下的time.Now() 分辨率在 Go 1.16 中得到了改进，参见#8687 和 CL #248699。

计时器的分辨率现在应该约为 500 纳秒。

测试程序：

package main

import (
    "fmt"
    "time"
)

func timediff() int64 {
    t0 := time.Now().UnixNano()
    for {
        t := time.Now().UnixNano()
        if t != t0 {
            return t - t0
        }
    }
}

func main() {
    var ds []int64
    for i := 0; i < 10; i++ {
        ds = append(ds, timediff())
    }
    fmt.Printf("%v nanoseconds\n", ds)
}

测试输出：

[527400 39200 8400 528900 17000 16900 8300 506300 9700 34100] nanoseconds

【讨论】：