runtime: modified timer results in extreme cpu load #51654
Description
What version of Go are you using (go version)?
Tracked down the issue to the following change: https://go-review.googlesource.com/c/go/+/336432
and issue: #47329
(including: https://go-review.googlesource.com/c/go/+/337309)
The issue exists from 1.16.7 and up, 1.17 and up, 1.18 and on master.
$ go version go version devel go1.19-3c2e73c8c3 Sun Mar 13 21:31:06 2022 +0000 linux/amd64
Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (go env)?
go env Output
$ go env GO111MODULE="" GOARCH="amd64" GOBIN="" GOCACHE="/root/.cache/go-build" GOENV="/root/.config/go/env" GOEXE="" GOEXPERIMENT="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOINSECURE="" GOMODCACHE="/go/pkg/mod" GONOPROXY="" GONOSUMDB="" GOOS="linux" GOPATH="/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/usr/local/go" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64" GOVCS="" GOVERSION="devel go1.19-3c2e73c8c3 Sun Mar 13 21:31:06 2022 +0000" GCCGO="gccgo" GOAMD64="v1" AR="ar" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="/dev/null" GOWORK="" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" PKG_CONFIG="pkg-config" GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3684654207=/tmp/go-build -gno-record-gcc-switches"
What did you do?
A K8s/Prometheus metrics exporter process started to sporadically give a high CPU load when updating the Go version.
The process gives 100% CPU usage up to ~2 minutes according to pidstat right after a TLS client connection has been setup and closed. The process is a http server and when a client connects a new TLS client connection is setup towards a 3rd entity to fetch metrics information.
The problem has been nailed down to a TLS write deadline timer that is modified by a P that is not owning the timer. This later on results in a "busy loop" around netpoll(delay) where a delay=0 is used.
This is the scenario:
-
A client connect to the HTTP server.
-
A new TLS client connection is setup towards a 3rd entity with a write deadline configured.
This sets the timer wt which previously is not on any P's heap.
In this example the setup is run on a p.id=0 which now puts timerwton the heap of P=0. -
The TLS client connection is closed after the communication is done via close()
In the scenario of this issue the close is performed on another P than was used during connect, in this example P=2.
The issue is not seen when the close is done by the same P used when opening the connection. -
During a close in TLS there is a call to closeNotify() which sets and reuses the timer wt.
Since this timer is still on the heap of P=0 it can't be modified from current P=2.
Insteadmodtimer()calls updateTimerModifiedEarliest() to setupdateTimerModifiedEarliestfor P=0 to 5s in the future. -
The next step in closeNotify() is to reset the timer to
now(), this will not trigger any change of the previously setupdateTimerModifiedEarliest.
TheupdateTimerModifiedEarliestcontains the timeout value for a timer that is no longer is used. -
The connection is now being closed and unregistreted via netpollclose()
-
Then I see that adjusttimers() for P=0 gets to run,
but after the corrections for issue time: Timer reset broken under heavy use since go1.16 timer optimizations added #47329 there is no longer any adjustments done, and the function just returns sincetimerModifiedEarliesthas not occurred yet. -
A couple of timeSleepUntil() finding P=0 and the
updateTimerModifiedEarliesttime set in step 4 can be seen. -
A call to checkTimersNoP() results in finding the
updateTimerModifiedEarliestvalue set in step 4. -
findrunnable() uses the result from step 9 to calculate delay=0 due to that the timeout value has already expired. The call to
netpoll()is not blocked/waiting.
Step 9 and 10 is now repeated for ~2 minutes, and this gives the high CPU load.
The "loop" seems to be interruptable by triggering a new connection via the HTTP server, or by itself after ~1m54s for a currently unknown reason.
Since I'm not that familiar with the runtime internals I have no correction proposal yet,
- but the switch of P that modify timers between step 2 and 3 seems to be the initial cause of the issue.
Maybe it has been triggered by astealWork()that haven't taken over the timers? - Another finding is that
updateTimerModifiedEarliestis only set when the new value is earlier than current,
so changing the timer in step 4 will not trigger a reset ofupdateTimerModifiedEarliesteven if the timer has changed.
Currently we can only reproduced the issue when running in containers via K8s/minikube, and it takes 15min to hours for it to show.
We have attempted to reproduce it via a testcase but have yet not succeeded, probably due to timing/num-of-threads/other.
I will update the issue with links how I setup a minikube deployment for reproduction,
but I'm also happy to provide more details about my runs or fetch more information.
Any advice is appreciated.
Here is a link to the steps taken when reproducing the issue:
https://github.com/bjosv/golang-devenv/tree/master/issue/timer-cpu-spike
What did you expect to see?
I expected the CPU load not to be affected by timers.
What did you see instead?
pidstat -p 1437245 1 when fetching metrics every 5s
03:53:58 PM UID PID %usr %system %guest %wait %CPU CPU Command 03:53:59 PM 59000 1437245 0,00 0,00 0,00 0,00 0,00 8 redis_exporter 03:54:00 PM 59000 1437245 1,00 0,00 0,00 0,00 1,00 8 redis_exporter 03:54:01 PM 59000 1437245 0,00 0,00 0,00 0,00 0,00 8 redis_exporter 03:54:02 PM 59000 1437245 0,00 0,00 0,00 0,00 0,00 8 redis_exporter 03:54:03 PM 59000 1437245 29,00 12,00 0,00 0,00 41,00 8 redis_exporter 03:54:04 PM 59000 1437245 75,00 26,00 0,00 0,00 101,00 8 redis_exporter 03:54:05 PM 59000 1437245 72,00 28,00 0,00 0,00 100,00 8 redis_exporter 03:54:06 PM 59000 1437245 75,00 25,00 0,00 0,00 100,00 8 redis_exporter 03:54:07 PM 59000 1437245 75,00 25,00 0,00 0,00 100,00 8 redis_exporter 03:54:08 PM 59000 1437245 42,00 20,00 0,00 0,00 62,00 8 redis_exporter 03:54:09 PM 59000 1437245 0,00 0,00 0,00 0,00 0,00 8 redis_exporter 03:54:10 PM 59000 1437245 0,00 0,00 0,00 0,00 0,00 8 redis_exporter
Running perf on a process during the CPU load, via pprof and perf_data_converter.
File: redis_exporter
perf-version:5.4.166
perf-command:/usr/lib/linux-tools-5.4.0-104/perf record -F 999 -g -p 256702
Type: cycles_event
Showing nodes accounting for 397249690343, 100% of 397249690343 total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
158127683505 96.67% | runtime.epollwait /usr/local/go/src/runtime/sys_linux_amd64.s:689
2450571955 1.50% | runtime.findrunnable /usr/local/go/src/runtime/proc.go:2767
2362278681 1.44% | runtime.findrunnable /usr/local/go/src/runtime/proc.go:2576
289069589 0.18% | runtime.usleep /usr/local/go/src/runtime/sys_linux_amd64.s:139
70082980 0.043% | runtime.(*randomEnum).next /usr/local/go/src/runtime/proc.go:6151
36979179 0.023% | runtime.stealWork /usr/local/go/src/runtime/proc.go:2892
33108497 0.02% | runtime.netpoll /usr/local/go/src/runtime/netpoll_epoll.go:124
24963444 0.015% | [x86_pkg_temp_thermal.ko]
19626310 0.012% | runtime.stealWork /usr/local/go/src/runtime/proc.go:2891
16466417 0.01% | runtime.pMask.read /usr/local/go/src/runtime/proc.go:5547
12265674 0.0075% | runtime.stealWork /usr/local/go/src/runtime/proc.go:2867
12027724 0.0074% | runtime.pMask.read /usr/local/go/src/runtime/proc.go:5544
8397722 0.0051% | runtime.(*randomEnum).next /usr/local/go/src/runtime/proc.go:6149
8110383 0.005% | runtime.(*randomOrder).start /usr/local/go/src/runtime/proc.go:6140
8004265 0.0049% | runtime.stealWork /usr/local/go/src/runtime/proc.go:2849
8001281 0.0049% | runtime.stealWork /usr/local/go/src/runtime/proc.go:2844
7890341 0.0048% | runtime.lock2 /usr/local/go/src/runtime/lock_futex.go:59
...
Metadata
Metadata
Assignees
Labels
Type
Projects
Status