runtime/metrics: add a way to measure runtime-internal lock contention

[rhysh]

Go's diagnostic tools give only a minimal view into contention on runtime-internal locks. I filed #57069 and #57070 with the best data available to me now. The story in #45894 has evolved over time. I haven't kept close track of the paths others take to finding runtime-internal lock contention, but I bet it's hard for them too. (Or: please share your techniques!)

The first one, #57069, appeared in the last few weeks while changing how we operate one of our apps. Pretty quick turnaround from seeing a problem to being able to describe it as a bug.

But #57070 describes a problem I've seen for years and wasn't quite sure I understood. In that app, we saw an increase in our CPU profiles' reports of time in runtime.futex when moving from Go 1.17 to 1.18 without any associated regression in the app's performance. I took that to mean that the change was only in the reporting, that those samples arrived in bursts and so were hidden by shortcomings in setitimer-based profiles. That helped to make sense of the execution traces, but the story was still hard to prove (to myself, and to you here) without having CPU profile samples inside the execution trace data stream.

I struggled with #45894 for a while before coming to understand that a lot of that post-GC delay was related to long waits on the runtime-internal mprof lock.

Maybe Go 1.19's tools are enough to get the job done, but I wonder if we should have a more direct measurement of contention and wait time on runtime-internal locks, like an equivalent of #49881.

CC @golang/runtime and @mknyszek

[prattmic]

I think it would be great if we could get the runtime locks fully wired up to the existing sync.Mutex contention profiles.

[rhysh]

Full wiring into runtime/pprof's sync.Mutex contention profile would be great. I'm anticipating that being at least a little tricky, since adding stacks to the mprof involves acquiring a lock.

With an intended end state of the data being part of that profile, I think 1/ the total wait time should be reported as part of /sync/mutex/wait/total:seconds rather than as a separate metric name, and 2/ that the wait time for runtime-internal locks should be reported in the profile with a temporary "best we could do" placeholder function name, similar to _LostSIGPROFDuringAtomic64. Maybe _LostRuntimeLockContention.

Then, as we move towards reporting the actual call stacks that led to contended runtime.lock calls, the data in /sync/mutex/wait/total:seconds will remain the same and fewer call paths will require being reported as _LostRuntimeLockContention and will instead have their real call stacks.

---

I'm inclined to add an atomic.Uint64 field to runtime.m to count the number of nanoseconds that this M has had to wait inside (sampled) lock2 calls where the "speculative grab" failed; I don't want to respond to contention on a runtime.lock by adding cross-M contention on a global reporting value. And then to sum those values, including a global pool for dead Ms, as we do for NumCgoCall.

It looks like I can call nanotime from within lock2.

Maybe I can also capture the call stack onto an array that is part of the runtime.m struct, but it's not clear to me when would be a good time to try adding its contribution to the mprof table. Once a stack is present in the table, we might be able to add weight to it without taking any locks (so safe to call from lock2). For getting the stack to appear there in the first place the challenge seems similar to the runtime.cpuProfile.extra mechanism, but that relies on other code executing on a regular basis in a less constrained environment. Maybe the equivalent here would be "sysmon" or "the GC", but those don't seem like great options.

---

• Is it good to report as /sync/mutex/wait/total:seconds?
• Because the docs for that metric say the Mutex profile will have more detail, is it OK to report those numbers as part of that profile with a bogus call stack (such as _LostRuntimeLockContention)?
• Is it OK to make the M struct larger, by a few words (counters) or by a few dozen words (call stack buffer)?
• Any feedback on my general plan, before I mail a CL that's heading towards a dead end?

@mknyszek @prattmic

Thanks!

[gopherbot]

Change https://go.dev/cl/528656 mentions this issue: runtime: remove lock from block/mutex profile

[gopherbot]

Change https://go.dev/cl/528657 mentions this issue: runtime: profile contended lock calls

[gopherbot]

Change https://go.dev/cl/534161 mentions this issue: runtime/metrics: add STW start and total time metrics

[rhysh]

@prattmic made a good point on https://go.dev/cl/528657 that the change includes an awkward mix of the semantics of the "mutex" and "block" profiles, by capturing the runtime.unlock call stack but using that M's own wait time as the value. To match the user-space "mutex" profile, its value should correspond to how long the other Ms were waiting for that critical section to complete. That's a more invasive change to src/runtime/lock_futex.go than we can make at this point in the Go 1.22 cycle.

@prattmic , @mknyszek and I discussed options at last week's "runtime diagnostics improvements" meeting: #57175 (comment) . The conclusion we came to is that we shouldn't ship those strange semantics as on by default for Go 1.22, but that we'd like to start getting the benefits of this from users who understand the current caveats and who understand that those semantics will soon change (improve). We're planning to do this via a GODEBUG setting that's off by default, and which will go away once the contention reports for runtime.mutex match those of sync.Mutex.

I updated https://go.dev/cl/528657 with a proposed name of GODEBUG=profileruntimelocks=1. When disabled, contention on runtime-internal locks is still reported in the /sync/mutex/wait/total:seconds metric, and is attributed to the runtime._LostContendedLock function.

If a temporary GODEBUG setting isn't appropriate here, we can disable the call stack collection in that same way for Go 1.22, attributing everything to the placeholder function so the /sync/mutex/wait/total:seconds metric and the sum of the mutex profile samples continue to match.

[gopherbot]

Change https://go.dev/cl/544195 mentions this issue: runtime: profile contended lock calls

[prattmic]

@rhysh FYI, I will be sending a release note CL for this. I don't want to race with you. :)

I also propose that we change the name of GODEBUG=profileruntimelocks=1 to GODEBUG=runtimecontentionstacks=1 and runtime._LostContendedLock to runtime._LostContendedRuntimeLock. I will send a CL for both.

My thought is that even with GODEBUG=profileruntimelocks=0 (the default), runtime locks are still profiled, we simply don't collect stacks. That makes the name confusing. Similarly, since users will see runtime._LostContendedLock in this case, I think runtime._LostContendedRuntimeLock is slightly more clear that this isn't one of the locks in their code.

[gopherbot]

Change https://go.dev/cl/547058 mentions this issue: doc: document runtimecontentionstacks

[gopherbot]

Change https://go.dev/cl/547057 mentions this issue: runtime/pprof: document block and mutex profiles

[gopherbot]

Change https://go.dev/cl/547055 mentions this issue: runtime: rename GODEBUG=profileruntimelocks to runtimecontentionstacks

[gopherbot]

Change https://go.dev/cl/547056 mentions this issue: runtime/metrics: document runtime-internal locks in /sync/mutex/wait/total:seconds

[gopherbot]

Change https://go.dev/cl/547059 mentions this issue: doc: add release notes for runtime-internal contention