Why does time.Now().UnixNano() returns the same result after an IO operation?

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

There's nothing wrong with your code. On windows the resolution of time is often higher than 1 ms. Meaning if you query the actual time twice within a millisecond, you often get the same value. Your operation sometimes yields `t = 2997600ns = 0.3μs`, which could explain this. Blame it on Windows. — icza, Jul 31 '19 at 07:34
Related: https://stackoverflow.com/q/21262821/13860 https://stackoverflow.com/q/3744032/13860 — Jonathan Hall, Jul 31 '19 at 07:38
@icza You are right! I run it on Linux, and there is no zero result. Thank you! — wayne, Jul 31 '19 at 07:43

icza · Accepted Answer · 2019-07-31T12:02:14.290

7

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()

edited Jul 31 '19 at 12:02

answered Jul 31 '19 at 07:44

icza

389,944
63
907
827

1

The system time has 100 ns precision, but it's only updated by the system timer interrupt every 15 ms or so. The timer resolution can be lowered to a millisecond or less, but this affects the scheduler and causes a significant increase in power consumption. If we need to measure precise intervals, as opposed to logging a system timestamp, we use the system performance counter instead, i.e. whatever way Go exposes WINAPI `QueryPerformanceCounter`. – Eryk Sun Jul 31 '19 at 11:35

score 0 · Answer 2 · answered Dec 09 '21 at 12:11

time.Now() resolution under Windows has been improved in Go 1.16, see #8687 and CL #248699.

The timer resolution should now be around ~500 nanoseconds.

Test program:

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

Test output:

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

Why does time.Now().UnixNano() returns the same result after an IO operation?

2 Answers2

Linked