time: inaccurate timer

[spance]

• What version of Go are you using (go version)?
  go version go1.6 linux/arm64
• What operating system and processor architecture are you using?
  ubuntu 14.04 kernel 4.2 aarch64
• What did you do?
  run "timer_testing.go"
• What did you expect to see?
  print "10ms" 10 times
• What did you see instead?
  some inaccurate duration

Test code "timer_testing.go"

package main

import (
    "fmt"
    "time"
)

func main() {
    tm := time.NewTicker(10e6) // 10ms
    t := time.Now()
    for i := 0; i < 10; i++ {
        <-tm.C
        now := time.Now()
        fmt.Println(now.Sub(t))
        t = now
    }
}

Run many times, I got some errors like this:

# ./timer_testing
10.156ms
10.023ms
404.745ms     # error
13.478ms       # error
1.84ms           # error
9.934ms
10.006ms
9.998ms
10.001ms
9.998ms

I have some programs that depend on accurate timing, those time error will result of some serious logic errors.

[kentquirk]

I'm not on the go team, but in general, timers are best-effort kinds of things in every general computing environment. Unless you're running on a real-time embedded operating system you can't rely on timer ticks to be accurate. You have two choices -- either spend cycles polling the real-time clock, and fire off your timer ticks yourself, or use the RTC to calculate the actual time spent (as you've done here) and adjust the result based on actual time elapsed.

In game development, you generally build your physics engine to take a deltaT parameter and pass that in on every tick, so that variable-time ticks average out. If you rely on timers to occur on a fixed interval, generally you'll lag behind as ticks go long or get delayed.

(Notice, by the way, that inside your timer loop you're doing a format and a print. That alone could be causing your problem.)

If it were up to me, I would close this as not a bug.

[minux]

If this is a bug, then it's a bug in the linux kernel. Try write the equivalent C program using usleep and gettimeofday and see what happens.

[spance]

I already knew the timers are best-effort kinds of things.
And I don't need that super high accurate timing (such as RTC...), I just hope the timer ticks could be as close to the ideal value.
In my tests, the time errors were often 400ms or 800ms or even more, which is already far more than the ideal value. (This test can be pass on x86/amd64).
I do not know the problem is caused by timer unit or runtime/goroutines scheduling unit or channel unit or others.
I will give the result by equivalent C program later.

[spance]

I wrote this C code and test it many times, here is the result:

root@hz:~# ./a.out
38545     #error
233960    #error
40192    #error
10217
10236
10264
10221
10229
10221
10213
10221
10222
10224
10222
10219
10222
10229
10235
10220
10218
root@hz:~# ./a.out
10172
10299
10271
10222
10217
10216
10216
10216
10217
10217
10215
10214
267447    #error
218768    #error
10270
330944    #error
691144    #error
10231
10214
10214

The C code:

#include <unistd.h>
#include <sys/time.h>
#include <stdio.h>

#define TO_US(x) x.tv_sec*1e6 + x.tv_usec

int main(){
    int i;
    long us, us2;
    struct timeval tv;
    gettimeofday(&tv, NULL);
    us=TO_US(tv);
    for(i=0;i<20;i++){
        usleep(10e3);
        gettimeofday(&tv, NULL);
        us2=TO_US(tv);
        printf("%ld\n", us2-us);
        us=us2;
    }
}

It may be a terrible problem of VM's provider, I'm sorry for opening this issue.

[rsc]

This is old and closed, but I just saw it while looking for something else and wanted to respond. The timer is ticking at a fixed rate whether you read from the channel or not, and even if the program is for whatever reason slow to read from the channel. The channel carries the original send time, which shows more accurately what is going on:

package main

import (
	"fmt"
	"time"
)

func main() {
	tm := time.NewTicker(10e6) // 10ms
	t := time.Now()
	start := t
	for i := 0; i < 100; i++ {
		now := <-tm.C
		fmt.Println(now.Sub(start))
	}
}

prints

$ go run /tmp/x.go
12.004696ms
21.612936ms
32.223175ms
42.088865ms
52.116363ms
61.359677ms
70.700632ms
81.505346ms
90.293924ms
102.533099ms
112.044295ms
120.437879ms
132.085239ms
142.11617ms
150.417673ms
162.480821ms
170.865435ms
182.427621ms
190.047232ms
...

You can see the timer is targeting ticking every 10ms. Sometimes it is a little late to send, but it doesn't let that skew later results. Instead it keeps up at a steady one-per-10ms, provided the receiver keeps up receiving.