runtime: findrunnableGCWorker consumed much higher CPU under 64c AWS instance (ARM64), comparing to 32c

[innerr]

Go version

go1.19.13 linux/arm64

Output of go env in your module/workspace:

GOARCH="arm64"

What did you do?

• We put one binary (developed/compiled by golang) in an AWS EKS instance, it runs as a gRpc server.
• Lately we changed this instance type, increasing CPU cores from 32c to 64c.

What did you see happen?

• We found that this process had much higher P999 latency comparing to previous.
• From flame graph, We found out findrunnableGCWorker consumed much higher CPU comparing to previous.

Here are the graphs:

• ARM64 32c:
  
• ARM64 64c:
  

What did you expect to see?

The latency of this server process shouldn't change much when we changed from 32c instance to 64c instance.

[seankhliao]

1.20 isn't a supported release, can we see the results from the latest version?

[rhysh]

Yes, reproducing on a newer Go version would make it easier to analyze the problem and perhaps to fix.

It's interesting to see runtime.(*gcControllerState).findRunnableGCWorker as the part of runtime.findRunnable that is consuming on-CPU time. That's guarded by a check of gcBlackenEnabled, so implies that the program is in the GC Mark phase.

Maybe the GC is running very often, which in turn has other effects that cause the app's increased tail latency. In that case, arranging for the GC to run less often (without changes to Go) might resolve your application's problems. Or, looking more deeply into the tail latency itself might show something about Go. Execution traces (the runtime/trace package) give a more direct view into latency.

---

One of the behaviors I've seen in the scheduler is that when there are a lot of Ps (higher GOMAXPROCS, since that's the number of runtime.p values in the program) it takes longer for an individual thread to find the runnable goroutines. That may be offset by the increased number of threads which are looking! When I've seen it, it's shown up as more on-CPU time in runtime.findRunnable's calls to runtime.stealWork.

It's interesting to see that your application ends up with higher latency. As I understand Go's scheduler, running a program with higher GOMAXPROCS would lead to higher CPU usage due to idle threads searching for work rather than going to sleep. But in a single-tenant environment -- with no other (big) programs running on the machine -- I'd expect the effect of that to be limited to keeping the CPUs powered up for longer than necessary, to waste electricity but to still have good latency in the app.

You mentioned AWS EKS, which makes me wonder if the app is running alongside other Go apps on the same machine/VM. If so, the increase in on-CPU times in the other Go apps (from the effect I described above) could be what's causing the latency.

---

It looks like the flame graph tool is reordering the functions based on their contribution to the on-CPU time total (rather than remaining alphabetical), which makes the two charts a bit hard to compare. Especially with the names being truncated. Sharing the data in a less processed form may be helpful, maybe the svg/web/png view of go tool pprof with -show_from=^runtime\. and/or -focus=^runtime\.findRunnable$.

The -list output for findRunnableGCWorker could also narrow down why that function is on-CPU for so much time, though I wonder if it's mainly due to a large number of calls rather than any of those calls being slow.

Looking at growth of the /sched/latencies:seconds buckets in the runtime/metrics package (summed, and multiplied by 8 to offset the sample rate of runtime.gTrackingPeriod) can give a view into how often the scheduler needs to make decisions.

[innerr]

Sorry it should be go1.19.13, my bad, and thanks for the rapid response!

[innerr]

By the way, this fig below is the effect to the server process, the latency is really bad at 64c: (single process in the k8s pod, no other apps)

[innerr]

Here are the flame graphs: (*.proto)
profile-2024-07-13_06-26-00.zip
profile-2024-07-07_06-28-00.zip

[rhysh]

Sorry it should be go1.19.13, my bad, and thanks for the rapid response!

Thanks for sharing the data. Those profiles work well with go tool pprof, including to annotate the matching lines of runtime source code.

I see that the Build ID for those two profiles are identical (e3ac319ed9aafff97d9ecf080dc2d206dd998382).

I see that the amount of on-CPU time they spend in several types of application goroutines is similar between the two profiles -- looks like they're receiving the same total amount of offered load (so half as much per core on the 64-core machine).

$ go tool pprof \
    -source_path=$HOME/sdk/go-bisect \
    -trim_path=/usr/local/go \
    -call_tree \
    -ignore=(runtime.schedule|runtime.gcDrain) \
    -web \
    /path/to/profile.pb.gz

From spot-checking differences in on-CPU time, I see that the 64-core profile shows more time in runtime.markroots. It's hard to know how much to read into this (or what to take from it) ... the CPU profiles average the application's behavior for their time window (10 seconds, in this case), so maybe these are capturing different portions of some small number of GC cycles.

Another overall takeaway from the CPU profiles is that the 32-core profile shows an average of about 10 cores of on-CPU time, and the 64-core profile shows an average of about 17 cores of on-CPU time. These don't appear (on average at least) to be starved for CPU time.

single process in the k8s pod, no other apps

With no other pods scheduled on the machine?

The change in how the program spends its CPU time is suspicious, but I don't see how that could connect to a delay in processing application work. When many Ps are in runtime.(*gcControllerState).findRunnableGCWorker's call to runtime.(*lfstack).pop, I'd expect that 1/ at least one of them is able to make progress, and so move on to doing other work and 2/ that even if there's a particular P that ends up stuck in lfstack.pop indefinitely, that any Gs on its local run queue would be available for other Ps to steal and execute.

I do see a difference in the amount of GC Assist work: from go tool pprof -peek=gcDrainN, 0.18% of the total matches for the 32-core profile, versus 2.39% for the 64-core profile. All of that is in the critical path of application work (and may also be in the critical path of the application's latency-sensitive work).

There may be two or more problems here. One relating to GC Assist, which could be a data point for Go's pacer design or could be worked around within your app. Another relating to the high on-CPU time in lfstack.pop.

Some thoughts on how to make analysis easier:
1/ A more recent (supported) version of Go, such as the Go 1.22 series. It's possible the bug is fixed, or is different, and in any case obtaining a fix for the bug will likely require updating the Go toolchain.
2/ Capturing execution traces (as in the runtime/trace package), and if possible having the app capture a CPU profile at the same time (which will result in the execution trace data stream including timestamped CPU profile samples, attached to the thread that observed them). It sounds like the main problem for your application is one of latency. The execution trace is the tool for measuring latency, including detailed sub-microsecond views into the behavior of the individual goroutines that collaborate to serve each request.

The golang.org/x/exp/trace.FlightRecorder may help to capture an execution trace that shows the problem. It requires Go 1.22.

CC @golang/runtime, and (pacer!? or at least GC worker management) @mknyszek

[innerr]

Appreciate the comprehensive response!

Since this issue happened on product env, we can't simply change the online app (change to go1.22 build),
So we are trying to re-produce this issue in offline env, then use go1.22 to capture necessary info.

If we are lucky, I should come back with new captured data in days. Thanks again!

[prattmic]

findRunnableGCWorker is one of the first checks in schedule. I wonder if this program is entering the scheduler extremely frequently (either due to explicit Gosched calls, or just short-lived runnable goroutines). Then all of the Ms are piling up on gcBgMarkWorkerPool. A trace would help to see if frequent scheduling is the case.

However, if that is the case, it is surprising we don't see other parts of the scheduler, for when the GC is not running.

[innerr]

Hi all, we ran some tests, and I am back with some test results and captured data.

Tests we did:

• Ran 64C/32C comparation on AWS EKS (ARM instances), re-produced the issue.
• We used "MAXPROCS=32" on 64C instance to simulate 32C instance, not ideal but we got the expected result.

Some things we found in the results:

• The issue mitigated after restarting the App:
  • We restarted our App, the latency reduced a lot
  • But still not as good as 32C.
• The issue mitigated slightly in go1.22.
• GOGC=? is helpfull:
  • This config reduced the tail latency in our tests, it also increase the latency jitter slightly but seems worth it comparing to longer tail latency.
  • The GOGC=? related fig is here:
    

And we captured flames with go1.22:

• 32C:
  • Captured data: 730-debug-32c-go1.22.zip
  • App performance:
• 64C:
  • Captured data: 730-debug-64c-go1.22.zip
  • App performance:

[rhysh]

Thanks for the update. Are you able to share the execution traces you collected?

Looking inside the zip files for the 32c and 64c experiments: The ./goroutine files make it look like the 32c process had been running for 7 minutes at the time of the snapshot and the 64c process had been running for 11 minutes. The ./mutex file shows 557 seconds of runtime._LostContendedRuntimeLock for the 32c process and 3500 seconds for the 64c process. That's about 1.3 thread-seconds and 5.3 thread-seconds respectively. That seems like a lot.

Using the CPU profiles in ./profile as a very rough estimate of which runtime-internal locks are contended via go tool pprof -peek '^runtime.lock($| )' -lines ./profile, I see a bit of sellock (to acquire channel locks inside a select statement, ok) but I see a lot in lines that reference sched.lock — and more in the 64c profile than with 32c.

This looks like evidence in favor of @prattmic 's suspicion that the program is entering the scheduler extremely frequently. That might be due to behavior of app-specific code, or due to behavior of a package the app uses (such as http2/grpc).

The 64c ./mutex profile shows 165e6 contention events taking 3500 seconds total, for an average of 21 µs per event. For 32c, it's 57e6 and 557, for an average of 9.8 µs per event. Those two processes also had a difference in the amount of sched.lock contention versus the amount of contention in sellock. It could be that the work within the locks' critical section is scaling poorly, or it could be that the work while holding sched.lock takes longer than the work done in selectgo (to implement select, following the contention in sellock). Or it could be that lock handoff is slower when more threads are at play. Or something else.

An execution trace, preferably one that was captured concurrently with an active CPU profile, would give a more complete view of what the app is doing and why it might be having trouble, rather than needing to piece bits together from the other views.

I have an idea for how to address the high CPU time of findRunnableGCWorker, but I'm not sure that's the cause of the latency. (Other processors should be able to pick up the runnable userspace goroutines.) I'll send a patch.

[gopherbot]

Change https://go.dev/cl/602477 mentions this issue: runtime: avoid futile mark worker acquisition