runtime: timer self-deadlock due to preemption point

[mknyszek]

The problem was discovered in kubernetes/kubernetes#88638, where Kubernetes was seeing some kubelets get wedged. They grabbed a stack trace for me, and after combing over it I summarized the problem. Below are the highlights:

[...] There's a self-deadlock going on in the timer system.

1. A goroutine does: timer.Reset -> resettimer -> modtimer -> wakeNetPoller
   • At this point, the timer its resetting is in the timerModifying state.
2. Now, at the beginning of wakeNetPoller, we get a preemption request (synchronous, so unrelated to asynchronous preemption), so we call into morestack.
3. The chain now goes morestack -> gopreempt_m -> goschedImpl -> schedule -> checkTimers -> runtimer
4. Now we try to run the timer we were modifying, but it's currently being modified, so we loop and osyield. It never stops being in timerModifying, though.

(kubernetes/kubernetes#88638 (comment))

[...] this can only happen if the timer is in the timerDeleted and at the top of the heap, and indeed (*time.Timer).Reset does stop (delete) the timer before resetting it. So, this doesn't imply a racy use of timers on Kubernetes' end.

Looking at the state machine in time.go again, [...] it could only ever happen with the wakeNetPoller call, because in addInitializedTimer we grab a runtime lock around cleantimers and doaddtimer, which prevents preemption.

Maybe what happened is that we accidentally inserted a preemption point? What if it was the case that in resettimer before wakeNetPoller was actually inlined, but in addInitializedTimer it's not. This means we added in a preemption point unintentionally.

One idea for the fix is to just... make sure wakeNetPoller gets inlined (and maybe https://go-review.googlesource.com/c/go/+/224902 actually does that), but that seems fragile. We should probably say that while a goroutine owns a timer in timerModifying it should not be allowed to be preempted, because it can cause an operation that waits (perhaps the same for other -ing states).

(kubernetes/kubernetes#88638 (comment))

CC @ianlancetaylor

[mknyszek]

@gopherbot Please open a backport to 1.14.

[gopherbot]

Backport issue(s) opened: #38072 (for 1.14).

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

[gopherbot]

Change https://golang.org/cl/225497 mentions this issue: runtime: prevent preemption while timer is in timerModifying

[bcmills]

Does this deadlock account for the test failures observed in #37894?

[bcmills]

(Looks like probably not.)

[mknyszek]

@bcmills It looks to me like those test failures are in fact this bug.

[mm4tt]

@mknyszek, thanks for debugging it and fixing it so quickly.
When can we expect the fix to be released?

[mvdan]

I think I've hit the same bug in a long-running server with many thousands of goroutines. This early morning, the process just froze forever - even a goroutine that was simply logging some trivial stats every minute or so was not responding. One of the runnable goroutines is at runtime.resettimer, so that's a bit suspicious, and how I found this bug.

2020-03-26-hang-log.txt.gz

@mknyszek do you think it's the same bug, or should I file a new one?

I should note that this is a server that works fine with Go 1.13.x, but started hanging like this since we jumped to 1.14.x. I had been testing it with 1.14.x for weeks before, but we hadn't started running the long-lived staging servers with 1.14.x.until earlier this week.

[ianlancetaylor]

@mm4tt The normal schedule for the next release would be next week some time.

@mvdan That is almost certainly the same bug.