go

Why is ticker.C not triggered in a select statement with default clause in a loop?


I've written some Go code which is supposed to send messages as fast as possible and do regular progress reports on this data. The code looks like the following:

messageGenerator := MessageGenerator{}

reportTicker := time.NewTicker(1 * time.Second)
defer reportTicker.Stop()

messagesSinceLastReport := 0

durationTimeout := time.After(duration)

for {
    select {
    case <-reportTicker.C:
        slog.Info("Sent messages during the last second", "amount", messagesSinceLastReport, "timestamp", time.Now().Unix())
        messagesSinceLastReport = 0
    case <-durationTimeout:
        return
    default:
        messageGenerator.writeNext(w)
        messagesSinceLastReport++
    }
}

However, the progress reports of the ticker seem to be unreliable. As an example, here is the output of a 10-minute run:

2025/01/05 18:34:03 INFO Starting to send messages as fast as possible duration=10m0s
2025/01/05 18:34:04 INFO Sent messages during the last second amount=297384 timestamp=1736098444
2025/01/05 18:34:14 INFO Sent messages during the last second amount=177057 timestamp=1736098454
2025/01/05 18:38:57 INFO Sent messages during the last second amount=321958 timestamp=1736098737
2025/01/05 18:44:31 INFO Sent messages during the last second amount=125510 timestamp=1736099071
2025/01/05 18:44:31 INFO Finished sending messages elapsedTime=10m28.031600479s

Why are the reports not printed once per second? Curiously, the timeout case is also triggered 28 seconds late. However, the fact that hundreds of thousands of messages are sent between the log statements makes me think that sending a single message should not be blocking for the full 28 seconds.

Shouldn't the reportTicker.C case have priority over the default case?


Solution

  • As suspected in Finn Bear's comment, the writeNext method was actually blocking for minutes and then writing hundreds of thousands of messages in a second.

    Extracting the message sending into a separate Goroutine and atomically incrementing the messagesSinceLastReport variable solved the issue for me.