time,runtime: too many concurrent timer firings for short time.Ticker

[mknyszek]

We've observed the "too many concurrent timer firings" panic, introduced in go.dev/cl/611496 for #69312, in production. We suspect they're due to relatively short time.Tickers.

This bug tracks figuring out why it happens and mitigating it. We expected this to be rare, and it still is relatively rare, but it does happen. go.dev/cl/620136 is a mitigation for time.Ticker that already landed on tip.

CC @ianlancetaylor

[gabyhelp]

Related Issues and Documentation

• runtime: avoid scary crash from concurrent calls to time.Timer.Reset #25686 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[mknyszek]

@gopherbot Please open a backport issue for Go 1.23.

This is a serious issue that affects users with no reasonable workaround. This issues does not affect Go 1.22.

[gopherbot]

Backport issue(s) opened: #69881 (for 1.22), #69882 (for 1.23).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://go.dev/wiki/MinorReleases.

[ianlancetaylor]

Fixed on tip, we think, by https://go.dev/cl/620136. Will reopen if it continues to occur.

[gopherbot]

Change https://go.dev/cl/620137 mentions this issue: [release-branch.go1.23] runtime: don't frob isSending for tickers

[jeromefroe]

Hi, my team has also observed occasional "too many concurrent timer firings" panics after upgrading to Go 1.23.2. In our case, the panics occur in a service that runs a gRPC server and my suspicion is that it may be because the gRPC server creates three new timers for each new connection:

idleTimer := time.NewTimer(t.kp.MaxConnectionIdle)
ageTimer := time.NewTimer(t.kp.MaxConnectionAge)
kpTimer := time.NewTimer(t.kp.Time)

In one case I saw that a replica that panicked had about 1000 active connections at the time it panicked. We initially suspected that this was a thundering herd problem in which too many clients try to connect to the service at once and thereby cause too many concurrent timers to be created, so we tried increasing the jitter the clients use when connecting to the service. Even with that change though we continued to observed panics in the service (I suspect this might be because the server resets the timers it creates so just due to random timing effects one might end up with many timers expiring at about the same time).

I'm still working on a reproducible example that I can share, but was curious if the linked CL would also effect timers or if it was only relevant to tickers?

[ianlancetaylor]

CL 620136 will only affect Tickers, not Timers.

Note that this crash is not the result of having many concurrent timers. It is the result of a single timer being run multiple times concurrently. Creating lots of timers can't cause this problem.

What can cause this problem is having a single timer that is reset multiple times very quickly to times that are in the past or the very near future. Each such timer reset can potentially lead to an immediate run of the timer. If those timer runs somehow happens 8 times concurrently, this error can occur. That said, I haven't been able to recreate this problem using timers. A test case would certainly be helpful.

[jeromefroe]

Thank you, that's incredibly helpful context. I had misunderstood the panic message, but this gives me a lead I can use to find the problematic goroutine in the stack traces emitted after the panics. Once I find the issue I'll see if I can turn it into a simple reproducible example.

[matbits]

So yesterday I also encountered this panic. It happened after 2-3 Hours and I found in my code the responsible code pattern:

func cleaner(ctx context.Context) {
	for {
		select {
		case <-ctx.Done():
			return
		case <-time.After(time.Millisecond):
			cleanup()
		}
	}
}

I know this is a bad pattern, I wanted to test the new golang 1.23 feature, that automically GCs unreferenced unstopped tickers. I refactored this code pattern to use only one Ticker:

func cleaner(ctx context.Context) {
	ticker := time.NewTicker(time.Millisecond)
	defer ticker.Stop()

	for {
		select {
		case <-ctx.Done():
			return
		case <-ticker.C:
			cleanup()
		}
	}
}

[ianlancetaylor]

@matbits Thanks. I don't see how the original cleaner function could cause the "too many concurrent timer firings" error. Can you describe why you think that caused the problem?

[matbits]

Good point, I thought the bug happened in my code and this is the only time I am using the time package with a ticker in my code. But maybe the panic happened inside of a third party library. I need to investigate this further

[gopherbot]

Change https://go.dev/cl/621616 mentions this issue: runtime,time: use atomic.Int32 for isSending

[gopherbot]

Change https://go.dev/cl/621856 mentions this issue: [release-branch.go1.23] runtime,time: use atomic.Int32 for isSending