为什么IO操作后time.Now（）。UnixNano（）返回相同的结果？

Question

I use time.Now().UnixNano() to calculate the execution time for some part of my code, but I find an interesting thing. The elapsed time is sometimes zero after an IO operation! What's wrong with it?

The code is running in Go 1.11, and use the standard library "time". Redis library is "github.com/mediocregopher/radix.v2/redis". The redis server version is 3.2. I'm running this on Windows, with VSCode Editor.

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

Here are some logs:

[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

Answer 1

There's nothing wrong with your code. On Windows, the system time is often only updated once every 10-15 ms or so, which means if you query the current time twice within this period, you get the same value.

Your operation sometimes yields t = 2997600ns = 3ms, which could explain this. Blame it on Windows.

Related questions:

How precise is Go's time, really?

How to determine the current Windows timer resolution?

Measuring time differences using System.currentTimeMillis()