Golang time.Ticker triggers twice after blocking a while-CodePudding

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?

CodePudding user response：

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.

CodePudding user response：

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.