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

In time.Ticker, there is a chan Time. In the NewTicker(d Duration) *Ticker function, It creates tickers Time channel as a buffered channel with capacity 1. In the function, it is mentioned as below.

// Give the channel a 1-element time buffer.
// If the client falls behind while reading, we drop ticks
// on the floor until the client catches up.

In your case, time ticks in every second and write to the channel. While sleeping, the ticker writes one time to the channel, and after the loop continues it is immediately received by select case and print. For the other 4 seconds, the channel is blocking and ticks are dropped. Immediately loop continues it is unblocked and accept more ticks to the channel.

Print the time comes through the channel and you can easily understand the behavior. Updated code as below.

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

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

Output:

2022/02/20 08:47:58 0 2022-02-20 08:47:58.773375 +0530 +0530 m=+1.004241004
2022/02/20 08:48:03 1 2022-02-20 08:47:59.772787 +0530 +0530 m=+2.003666993
2022/02/20 08:48:03 2 2022-02-20 08:48:03.774272 +0530 +0530 m=+6.005207433 // printing time is same, but channel's received time has 4 sec difference.
2022/02/20 08:48:04 3 2022-02-20 08:48:04.774203 +0530 +0530 m=+7.005151715

Run in Playground.