sync: higher mutex wait durations in 1.24

[hossein-raeisi]

Go version

1.24

Output of go env in your module/workspace:

AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE='on'
GOAMD64='v1'
GOARCH='amd64'
GOAUTH='netrc'
GOBIN=''
GOCACHEPROG=''
GODEBUG=''
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build322822516=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOOS='linux'
GOROOT='/usr/lib/go'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/lib/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.24.0'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

Upgraded a grpc serving applciation's golang version from 1.23.3 to 1.24.0 (and 1.24.1) (The application is more on the io-bound side)

What did you see happen?

Mutex wait duraion increased by a factor of 2 after the upgrade. the issue seems to be with an unlock in context.(*cancelCtx).propagateCancel

Prometheus metrics:
go_sync_mutex_wait_total_seconds_total

(At 1130 the upgraded version was deployed on yellow)

Pprof profiles:

(Left side is go 1.24 and right side is 1.23)

What did you expect to see?

It's mentioned in 1.24's release notes that cpu performance is improved via some changes including a new runtime-internal mutex implementation [ref]. I'm wondering if that could've caused some related issues?

[seankhliao]

I think we'll need more information, a reproducer, and maybe try with the GOEXPERIMENT=nospinbitmutex option.

[gabyhelp]

Related Issues

• runtime: spinbitmutex performance differs between 1.24.0 and 1.24.1, what changed? #72117 (closed)
• runtime: ~5% regression in ParallelizeUntil/pieces:1000,workers:10,chunkSize:1-8 sec/op at 450ecbe #64455
• runtime: MutexProfile missing root frames in go1.23 #69335 (closed)
• sync: performance drop with mutex #5183 (closed)
• runtime/pprof: change in behavior between Go 1.13 and 1.14 #36874 (closed)
• runtime/pprof: block and mutex profile stacks sometimes have "gowrap" root frames #69294
• sync: Mutex performance collapses with high concurrency #33747 (closed)
• runtime: async preemption causes short sleep in tickspersecond #63103 (closed)
• runtime: MutexProfile has multiple records with equal stack #67548 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[rhysh]

You've described how the diagnostic metrics changed when updating to go1.24.0. Can you share how the application-level performance changed, if at all?

And, can you put the magnitude of delay in context, comparing it to the number of total thread-seconds or goroutine-seconds in the app? For instance, does this mean the app spends 0.1% of its time blocked, or 0.0001%? As a bonus, how does it compare to the amount of time that goroutines spend waiting to be scheduled (summing the buckets of /sched/latencies:seconds)?

---

The flame graph screenshot shows changes across the board to which functions have reportable mutex contention. The calls under the "my service" label used to have 60% of their sub-calls to a package other than "context", but that's disappeared from the new profile on the left, with 90%+ of its reported time now attributed to context.(*cancelCtx).propagateCancel via context.WithTimeout. Unless there's a slow AfterFunc call (unlikely, I'd guess), the critical section looks quite short: https://github.com/golang/go/blob/go1.24.0/src/context/context.go#L484-L494

With the information available here so far, I wonder if GOEXPERIMENT=spinbitmutex is resulting in small changes to the order that threads and goroutines are able to execute, which leads to existing forms of delay being reclassified as "mutex wait". (A goroutine can only count as waiting on a mutex if it's been scheduled for long enough to reach the Lock call. Time it spends in a run queue before making that call doesn't count.)

I'm also suspicious of the amount of time that's still attributed to runtime._LostContendedRuntimeLock. I'd expect that to be very small: First, runtime-internal locks have small and well-controlled critical sections, so each instance of delay would usually be quite small relative to an app's other work. Second, platforms (including linux/amd64) that use GOEXPERIMENT=spinbitmutex will report the call stacks when they experience contention, even without GODEBUG=runtimecontentionstacks=1, rather than attributing them to runtime._LostContendedRuntimeLock. But I don't see call stacks in the new/left profile that show runtime internals.

---

Describing the app-level regression, if any, would be helpful here. The critical sections involved seem quite small, and the overall delay (without additional information) seems quite small. It's alarming to see something double, but a small number that's doubled is still a small number. Showing that it's large relative to the app (such as relating it to the total scheduling latency over the same time period) could help.

[hossein-raeisi]

Using the GOEXPERIMENT=nospinbitmutex flag didn't help the issue.

Haven't had the time yet, but i'll try to create a small reproducer.

---

I couldn't conclude meaningful affects on the application overally. Most of the services APIs are io-bound and their latency bottleneck is somewhere else. There is somewhat of a regression on the latency of few internally computed APIs, but not a confidant and provable change. (Though, we've gone forward with the upgrade at the moment. As @rhysh mentioned, the latency is a still a samll value.)

---

To put it in perspective, for around 15 seconds of cpu time samples for context.Timeout, there is 3 seconds of internal/sync.(*Mutex).Unlock.

Relation of mutex wait and scheduler latency:

(yellow upgraded around 1130)

Other calls haven't disappear from the graph but are smaller now. Maybe visualizing the differnece of flame graphs helps to understand it better:

They rather take a lesser portion of time in 1.24.

Not sure about the load contentention data, the profiles are generated with standard settings of pprof + runtime.SetMutexProfileFraction. Is there any configurations I could include to get the full stack trace?

[hossein-raeisi]

Sorry for the wait. Here's a similar but simple reproducer for the issue:

Repo

Mutex wait for builds with differenet golang versions:

[rhysh]

Second, platforms (including linux/amd64) that use GOEXPERIMENT=spinbitmutex will report the call stacks when they experience contention, even without GODEBUG=runtimecontentionstacks=1, rather than attributing them to runtime._LostContendedRuntimeLock.

That was incorrect, sorry. Nothing suspicious there. (Removing that setting is part of #66999, which isn't done yet.)

Using the GOEXPERIMENT=nospinbitmutex flag didn't help the issue.

Thanks for checking. That, plus my corrected understanding of why runtime._LostContendedRuntimeLock shows up (it's still for any runtime-internal contention when GODEBUG=runtimecontentionstacks has its default setting .. I thought I'd changed that for spinbitmutex platforms), makes it look like this isn't at all related to the runtime-internal lock changes.

---

I'm not sure there's a problem here. The reported contention (in particular, in context.(*cancelCtx).propagateCancel) went up, but it's small relative to the app (moving from 5% up to 15% of the amount of time that runnable goroutines spend waiting to be scheduled). But if it's not causing problems for the app, then I'm not sure what (if anything) there is to do about the change in the metric.