time: Timer ticks at incorrect time.

[GrimTheReaper]

What version of Go are you using (go version)?

go version go1.8 linux/amd64

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/wtsadmin/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

https://play.golang.org/p/ksmG70ZspO

Playground wont work, as the application takes too long to do anything.

This application is expected to tick at every 3rd minute, divisible by 3, at the zero second. The main func calls the func runningRoutine which then starts a ticker which is scheduled to report back on chan ticker.C.

What did you expect to see?

2017-03-31 17:12:00 +0000 UTC - next tick
2017-03-31 17:12:00.679440834 +0000 UTC - just ticked
2017-03-31 17:15:00 +0000 UTC - next tick
2017-03-31 17:15:00.166336427 +0000 UTC - just ticked
2017-03-31 17:18:00 +0000 UTC - next tick

What did you see instead?

This is the first tick, which it drifts, but the drifting gets worse, up to a minute, after a few ticks.

2017-03-31 17:12:00 +0000 UTC - next tick
2017-03-31 17:12:02.679440834 +0000 UTC - just ticked
2017-03-31 17:15:00 +0000 UTC - next tick
2017-03-31 17:13:53.166336427 +0000 UTC - just ticked
2017-03-31 17:15:00 +0000 UTC - next tick

[rsc]

This program doesn't do what you think it does:

package main

import (
	"fmt"
	"time"
)

func main() {
	runningRoutine()
}

func runningRoutine() {
	ticker := updateTicker()
	for range ticker.C {
		fmt.Println(time.Now(), "- just ticked")
		ticker = updateTicker()
	}
}

func updateTicker() *time.Ticker {
	ct := time.Now()

	nextTick := time.Date(ct.Year(), ct.Month(), ct.Day(), ct.Hour(), ((ct.Minute()/3)+1)*3, 0, 0, time.Local)
	fmt.Println(nextTick, "- next tick")
	diff := nextTick.Sub(time.Now())
	return time.NewTicker(diff)
}

The for range ticker.C evaluates ticker.C just once, when the loop begins. It uses that channel for the entire loop. Reassigning ticker has no effect. The initial ticker is used for the whole program execution. If you want the reassignment of ticker to have an effect you need to use:

for {
    <-ticker.C
    ...
}

instead.

[GrimTheReaper]

@rsc changing the code to what you suggested still has the same issue, where the ticker is ticking later than when it should.

[rsc]

I don't know, this seems to work fine for me:

package main

import (
	"fmt"
	"time"
)

func main() {
	t := time.NewTicker(3 * time.Second)
	for {
		<-t.C
		fmt.Println(time.Now())
		later := time.Now().Add(5 * time.Second).Round(5 * time.Second)
		t = time.NewTicker(time.Until(later))
	}
}

[rsc]

Note that it does generate a lot of garbage tickers that never stop and fill up the timer heap, so they will slow down your program over a very long time. Really the code should t.Stop() before starting a new one, or use time.After. But it works fine for me.

[rsc]

Also note that time.Ticker already takes care of firing multiple times and making sure it stays aligned to its initial start. So this would be even easier:

package main

import (
	"fmt"
	"time"
)

func main() {
	time.Sleep(time.Until(time.Now().Add(5 * time.Second).Truncate(5 * time.Second)))
	for range time.NewTicker(5 * time.Second).C {
		fmt.Println(time.Now())
	}
}

[GrimTheReaper]

@rsc
Running your code seems to provide interesting results.
VM on Azure

2017-04-03 13:31:39.903273512 +0000 UTC
2017-04-03 13:31:44.806360522 +0000 UTC
2017-04-03 13:31:49.709521699 +0000 UTC
2017-04-03 13:31:54.612722284 +0000 UTC
2017-04-03 13:31:59.515801144 +0000 UTC
2017-04-03 13:32:04.418899557 +0000 UTC
2017-04-03 13:32:09.321799237 +0000 UTC
2017-04-03 13:32:14.224852982 +0000 UTC
2017-04-03 13:32:19.128250059 +0000 UTC
2017-04-03 13:32:24.031184079 +0000 UTC
2017-04-03 13:32:28.93432498 +0000 UTC

On my Computer

2017-04-03 08:31:40.000241698 -0500 CDT
2017-04-03 08:31:45.000246225 -0500 CDT
2017-04-03 08:31:50.000238829 -0500 CDT
2017-04-03 08:31:55.000217211 -0500 CDT
2017-04-03 08:32:00.000234417 -0500 CDT
2017-04-03 08:32:05.000246416 -0500 CDT
2017-04-03 08:32:10.00024682 -0500 CDT
2017-04-03 08:32:15.000231732 -0500 CDT
2017-04-03 08:32:20.000238135 -0500 CDT
2017-04-03 08:32:25.000250395 -0500 CDT
2017-04-03 08:32:30.000248933 -0500 CDT

[rsc]

@GrimTheReaper Try using current Go master instead of Go 1.8. It will show the monotonic times in the print too. The most likely answer is that the Azure VM is running its monotonic clock at 5s/5s but the real time clock at 4.9s/5s, for whatever reason. If you don't have Go master handy for building, I've attached a zip with a Linux binary of the program.

issue19810.zip

[GrimTheReaper]

@rsc I'll try that out, and post back results. Thank you for having the time to help btw. 👍

[GrimTheReaper]

Here are the results.

Azure VM:

2017-04-03 13:56:59.802457307 +0000 UTC m=+9.810261880
2017-04-03 13:57:04.703557717 +0000 UTC m=+14.810294976
2017-04-03 13:57:09.604660189 +0000 UTC m=+19.810321211
2017-04-03 13:57:14.505616482 +0000 UTC m=+24.810280416
2017-04-03 13:57:19.40656589 +0000 UTC m=+29.810294981
2017-04-03 13:57:24.307681022 +0000 UTC m=+34.810281038

[rsc]

It does seem that for whatever reason your VM's monotonic timer is running (1+2/99)X faster than wall time, assuming wall time is correct. It's not that uncommon for virtualization to affect the different clocks differently, for what it's worth, although I don't have any guesses about where 2/99 comes from.

[GrimTheReaper]

@rsc reading other blog post and talking to a few people who use Azure on a daily bases, it seems that Microsoft's VMs will always be off, and other people have this same issue.

Although this is no longer a Golang issue, do you have any advice on what I should do from here on out?

[rsc]

Instead of using a repeating ticker I would suggest using either time.Sleep or time.After (which only ticks once) and then recalculate the wall clock delta on each iteration. Like you were doing in the first example, but without time.Ticker and without the range loop.

Using sleep it would look like:

package main

import (
	"fmt"
	"time"
)

func waitUntilAligned(align time.Duration) {
	d := time.Until(time.Now().Add(align).Truncate(align))
	// d = d * 101 / 99
	time.Sleep(d)
}

func main() {
	for {
		waitUntilAligned(5 * time.Second)
		fmt.Println(time.Now())
	}
}

If you're doing 3 minute sleeps then you're going to wake up about 3.5 seconds early due to the sleep running faster than wall time. If that is important, you could assume the Azure constant is stable (it seems quite stable in the test at least) and uncomment the adjustment in waitUntilAligned.

Or you could go super-fancy and have the implementation watch the skew and adjust (comment out fakeAzure = true for real use, although it will work either way). If the clock is fast the ticks will still always come slightly early even corrected. You could ask for the tick to come at an offset from the actual aligned time to shove it forward. The code below tries for 5s aligned + 0.01s offset (also at https://play.golang.org/p/jSpAiz6piq):

package main

import (
	"fmt"
	"time"
)

type WallTicker struct {
	C      <-chan time.Time
	align  time.Duration
	offset time.Duration
	stop   chan bool
	c      chan time.Time
	skew   float64
	d      time.Duration
	last   time.Time
}

func NewWallTicker(align, offset time.Duration) *WallTicker {
	w := &WallTicker{
		align:  align,
		offset: offset,
		stop:   make(chan bool),
		c:      make(chan time.Time, 1),
		skew:   1.0,
	}
	w.C = w.c
	w.start()
	return w
}

const fakeAzure = true

func (w *WallTicker) start() {
	now := time.Now()
	d := time.Until(now.Add(-w.offset).Add(w.align * 4 / 3).Truncate(w.align).Add(w.offset))
	d = time.Duration(float64(d) / w.skew)
	w.d = d
	w.last = now
	if fakeAzure {
		d = time.Duration(float64(d) * 99 / 101)
	}
	time.AfterFunc(d, w.tick)
}

func (w *WallTicker) tick() {
	const α = 0.7 // how much weight to give past history
	now := time.Now()
	if now.After(w.last) {
		w.skew = w.skew*α + (float64(now.Sub(w.last))/float64(w.d))*(1-α)
		select {
		case <-w.stop:
			return
		case w.c <- now:
			// ok
		default:
			// client not keeping up, drop tick
		}
	}
	w.start()
}

func main() {
	for range NewWallTicker(5*time.Second, 10*time.Millisecond).C {
		fmt.Println(time.Now())
	}
}

[GrimTheReaper]

@rsc
Thank you :)