time: Timer reset broken under heavy use since go1.16 timer optimizations added [1.16 backport] #47332

gopherbot · 2021-07-22T03:00:34Z

@ianlancetaylor requested issue #47329 to be considered for backport to the next 1.16 minor release.

@gopherbot Please open backport to 1.16.

This bug also exists in 1.16. It can cause programs that use Timer.Reset to fail to run a timer when it is ready.

The text was updated successfully, but these errors were encountered:

toothrot · 2021-07-22T18:22:05Z

Approved. This is a serious issue with no workaround.

gopherbot · 2021-07-22T19:27:47Z

Change https://golang.org/cl/336689 mentions this issue: [release-branch.go1.16] runtime: don't clear timerModifiedEarliest if adjustTimers is 0

gopherbot · 2021-07-22T21:53:43Z

Closed by merging ed8cbbc to release-branch.go1.16.

… adjustTimers is 0 This avoids a race when a new timerModifiedEarlier timer is created by a different goroutine. For #47329 Fixes #47332 Change-Id: I6f6c87b4a9b5491b201c725c10bc98e23e0ed9d1 Reviewed-on: https://go-review.googlesource.com/c/go/+/336432 Trust: Ian Lance Taylor <iant@golang.org> Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Michael Knyszek <mknyszek@google.com> (cherry picked from commit 798ec73) Reviewed-on: https://go-review.googlesource.com/c/go/+/336689

dmitshur · 2021-07-27T20:13:08Z

@ianlancetaylor Should the follow up change CL 337309 also be cherry-picked to 1.16?

(I'll reopen this so we don't forget to make that decision before release time.)

ianlancetaylor · 2021-07-27T21:06:48Z

I'm uncertain whether CL 337309 should be cherry picked to the 1.16 branch. The bug fix (CLs 336432, 336689) fixed a real bug that could cause timers to fail to fire. CL 337309 is a performance fix. I'm mildly concerned that CL 337309 will introduce some other unforeseen performance problem. On the 1.16 release branch we needed the bug fix, but I don't know how hard we want to change performance issues on that branch.

cagedmantis · 2021-07-29T18:17:58Z

Closed per Ian's comment.

tmm1 · 2021-07-30T04:40:59Z

FYI I'm seeing increased CPU usage on various x64 and arm64 linux nodes after rolling out ed8cbbc. I will rollback to 1.16.6 tomorrow to confirm and capture some cpu profiles.

EDIT: I confirmed reverting that single commit brought the cpu usage of my otherwise idle golang program from 100% back to 0%.

Here's a 60s cpu profile with that commit included:

(pprof) top --cum
Showing nodes accounting for 49.47s, 82.42% of 60.02s total
Dropped 25 nodes (cum <= 0.30s)
Showing top 10 nodes out of 26
      flat  flat%   sum%        cum   cum%
     4.17s  6.95%  6.95%     60.01s   100%  runtime.findrunnable
         0     0%  6.95%     58.82s 98.00%  runtime.schedule
         0     0%  6.95%     58.76s 97.90%  runtime.mcall
         0     0%  6.95%     58.63s 97.68%  runtime.park_m
     3.91s  6.51% 13.46%     42.10s 70.14%  runtime.netpoll
    38.19s 63.63% 77.09%     38.19s 63.63%  runtime.epollwait
     1.90s  3.17% 80.26%      4.70s  7.83%  runtime.checkTimers
     1.25s  2.08% 82.34%      1.54s  2.57%  runtime.nanotime (inline)
     0.01s 0.017% 82.36%      1.42s  2.37%  runtime.unlock (inline)
     0.04s 0.067% 82.42%      1.41s  2.35%  runtime.unlockWithRank (inline)

and back to normal after I reverted it:

(pprof) top --cum
Showing nodes accounting for 30ms, 75.00% of 40ms total
Showing top 10 nodes out of 17
      flat  flat%   sum%        cum   cum%
         0     0%     0%       20ms 50.00%  runtime.gcBgMarkWorker
         0     0%     0%       20ms 50.00%  runtime.gcBgMarkWorker.func2
      10ms 25.00% 25.00%       20ms 50.00%  runtime.gcDrain
         0     0% 25.00%       20ms 50.00%  runtime.mcall
         0     0% 25.00%       20ms 50.00%  runtime.park_m
         0     0% 25.00%       20ms 50.00%  runtime.schedule
         0     0% 25.00%       20ms 50.00%  runtime.systemstack
      10ms 25.00% 50.00%       10ms 25.00%  runtime.epollwait
         0     0% 50.00%       10ms 25.00%  runtime.findrunnable
      10ms 25.00% 75.00%       10ms 25.00%  runtime.futex

tmm1 · 2021-07-30T14:31:14Z

The CPU usage issue was also observed on macOS and Windows nodes, and was also fixed there after rolling back this commit.

ianlancetaylor · 2021-07-30T17:08:46Z

What can you tell us about the way in which your program uses timers and deadlines?

Does the change in https://golang.org/cl/337309 fix the problem?

Thanks.

tmm1 · 2021-07-30T17:55:22Z

I will try a build with that CL now. I'm testing on an arm64 rpi4 which consistently shows 100% cpu usage with the bad commit.

My program has a number of goroutines which run infinite loops as so:

for {
	select {
	case <-time.After(3 * time.Hour):
	case <-r.wakeup:
	case <-r.quit:
		r.quit <- true
		return
	}

	...
}

tmm1 · 2021-07-30T18:00:43Z

CPU usage is normal with https://golang.org/cl/337309 applied.

ianlancetaylor · 2021-07-30T18:33:40Z

Thanks for testing. I will backport 337309 to the 1.16 branch.

gopherbot · 2021-07-30T18:36:25Z

Change https://golang.org/cl/338649 mentions this issue: [release-branch.go1.16] runtime: remove adjustTimers counter

ianlancetaylor · 2021-07-30T20:45:36Z

Backport complete.

In CL 336432 we changed adjusttimers so that it no longer cleared timerModifiedEarliest if there were no timersModifiedEarlier timers. This caused some Google internal tests to time out, presumably due to the increased contention on timersLock. We can avoid that by simply not skipping the loop in adjusttimers, which lets us safely clear timerModifiedEarliest. And if we don't skip the loop, then there isn't much reason to keep the count of timerModifiedEarlier timers at all. So remove it. The effect will be that for programs that create some timerModifiedEarlier timers and then remove them all, the program will do an occasional additional loop over all the timers. And, programs that have some timerModifiedEarlier timers will always loop over all the timers, without the quicker exit when they have all been seen. But the loops should not occur all that often, due to timerModifiedEarliest. For #47329 For #47332 Change-Id: I7b244c1244d97b169a3c7fbc8f8a8b115731ddee Reviewed-on: https://go-review.googlesource.com/c/go/+/337309 Trust: Ian Lance Taylor <iant@golang.org> Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Michael Pratt <mpratt@google.com> (cherry picked from commit bfbb288) Reviewed-on: https://go-review.googlesource.com/c/go/+/338649

lukestoward · 2021-09-06T11:26:38Z

I've been trying to diagnose an issue relating to short sharp CPU spikes which sound similar to @tmm1's comment above. I'm running a http server that configures a read (5 secs), write (10 secs) and idle (15 secs) timeout. I found that when using Go 1.16.6 the CPU usage is stable, however when using 1.16.7 I see several 100% CPU spikes lasting <2 mins over a 24 hour period. I have been unable to correlate the spikes with any other metric. It appears to be random. HTTP traffic ranges from several request per minute to 10,000+.

If I remove the IdleTimeout value on the http server, falling back to the default, as per the documentation, I do not see any CPU spikes. For a little while now I've been trying to reproduce the issue with a minimal example unsuccessfully. I'm convinced the changes to src/runtime/time.go in 1.16.7 introduced a bug, but I'm having difficulty proving it. Any suggestions on what I might be able to try/do to help provide more information?

ianlancetaylor · 2021-09-06T17:06:31Z

@lukestoward This issue is closed and as far as we can tell, it is fixed. The fix was in the Go 1.16.7 release. Although the fix may well have introduced the problem you describe, since the patch has been released we should treat this as a new problem. I encourage you to open a new issue, ideally with a case that we can use to reproduce the problem.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

time: Timer reset broken under heavy use since go1.16 timer optimizations added [1.16 backport] #47332

time: Timer reset broken under heavy use since go1.16 timer optimizations added [1.16 backport] #47332

gopherbot commented Jul 22, 2021

toothrot commented Jul 22, 2021

gopherbot commented Jul 22, 2021

gopherbot commented Jul 22, 2021

dmitshur commented Jul 27, 2021 •

edited

ianlancetaylor commented Jul 27, 2021

cagedmantis commented Jul 29, 2021

tmm1 commented Jul 30, 2021 •

edited

tmm1 commented Jul 30, 2021

ianlancetaylor commented Jul 30, 2021

tmm1 commented Jul 30, 2021

tmm1 commented Jul 30, 2021

ianlancetaylor commented Jul 30, 2021

gopherbot commented Jul 30, 2021

ianlancetaylor commented Jul 30, 2021

lukestoward commented Sep 6, 2021

ianlancetaylor commented Sep 6, 2021

time: Timer reset broken under heavy use since go1.16 timer optimizations added [1.16 backport] #47332

time: Timer reset broken under heavy use since go1.16 timer optimizations added [1.16 backport] #47332

Comments

gopherbot commented Jul 22, 2021

toothrot commented Jul 22, 2021

gopherbot commented Jul 22, 2021

gopherbot commented Jul 22, 2021

dmitshur commented Jul 27, 2021 • edited

ianlancetaylor commented Jul 27, 2021

cagedmantis commented Jul 29, 2021

tmm1 commented Jul 30, 2021 • edited

tmm1 commented Jul 30, 2021

ianlancetaylor commented Jul 30, 2021

tmm1 commented Jul 30, 2021

tmm1 commented Jul 30, 2021

ianlancetaylor commented Jul 30, 2021

gopherbot commented Jul 30, 2021

ianlancetaylor commented Jul 30, 2021

lukestoward commented Sep 6, 2021

ianlancetaylor commented Sep 6, 2021

dmitshur commented Jul 27, 2021 •

edited

tmm1 commented Jul 30, 2021 •

edited