Golang time.Ticker triggers twice after blocking a while

Question

I'm using time.Ticker with some blocking code, found a strange behavior:

func main() {
    ticker := time.NewTicker(1 * time.Second)

    i := 0
    for {
        select {
        case <-ticker.C:
            log.Println(i)
            if i == 0 {
                time.Sleep(5 * time.Second) // simulate the blocking
            }
            i++
        }
    }
}

A sample output:

2022/02/20 10:49:45 0
2022/02/20 10:49:50 1 <- shows at same time
2022/02/20 10:49:50 2 <- shows at same time
2022/02/20 10:49:51 3
2022/02/20 10:49:52 4
2022/02/20 10:49:53 5
...

The "1" and "2" always shown at same time, why is that?

Answer 1

The ticker creates a buffered channel with a capacity of one. The ticker drops time values when the channel is full.

Here's the timeline for the trace in the question. Events listed for the same time happen a tiny bit after each other in the order listed.

1s - ticker sends value
1s - main goroutine receives first value
1s - main goroutine starts sleep for 5s
2s - ticker sends value (channel has capacity 1).
3s - ticker fails to send value because channel is full
4s - ticker fails to send value because channel is full
5s - ticker fails to send value because channel is full
6s - main goroutine exits sleep and receives buffered value
6s - ticker sends value
6s - main goroutine receives buffered value

The ticker and main goroutine race to the 6s mark because the sleep is a multiple of the ticker period. In your trace, the main goroutine wins the race. On my machine, the ticker wins the race and I get the timing that you expect. Here's what it looks like on my machine.

...
5s - ticker fails to send value because channel is full
6s - ticker fails to send value because channel is full
6s - main goroutine receives buffered value
7s - ticker sends value
7s - main goroutine receives value

The ticker wins the race to the 6s mark on the playground. Run it here. The main goroutine wins the race when the sleep time is nudged down by a 1µs. Run it here.

This is easy to see when the sleep duration is not a multiple of the ticker period. Here's what happens when the sleep duration is 2.5 seconds:

1s - ticker sends value
1s - main goroutine receives first value
1s - main goroutine starts sleep for 2.5s
2s - ticker sends value
3s - ticker fails to send value because channel is full
3.5s - main goroutine exits sleep and receives buffered value
4s - ticker sends value
4s - main goroutine receives value

Run the last example on the playground.