runtime: etcd put 5% throughput regression

[mknyszek]

https://perf.golang.org/dashboard/?benchmark=EtcdPut-88&unit=sec%2Fop&repository=go&branch=master&platform=linux%2Famd64&days=30&end=2025-05-30T02%3A07

The regression happened around commits 4d0f955 and 4e63ae4, though the former seems more of a culprit than the latter. (It's kind of hard to tell though.)

We should at least investigate and understand what's going on here.

CC @rhysh @randall77 @prattmic

[prattmic]

Hopefully a profile will make this fairly clear. Are they heavy on runtime locks or on maps?

[mknyszek]

The only thing I know for sure is that this benchmark is not heavy on GC, so if it's a lock, it's (probably) not a lock in the GC.

[gabyhelp]

Related Issues

• runtime: stack growth during critical section harms performance #18020

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

[randall77]

I did a differential profile between commits ab2a92d and ec7d955 (a few commits before and after the slowdown in question). The top 20 are here:

      flat  flat%   sum%        cum   cum%
     0.41s  0.86%  0.86%     -0.08s  0.17%  runtime.selectgo
    -0.21s  0.44%  0.42%     -0.21s  0.44%  runtime.nanotime (inline)
     0.17s  0.36%  0.77%      0.29s  0.61%  runtime.mutexSampleContention (inline)
    -0.14s  0.29%  0.48%     -0.10s  0.21%  runtime.mallocgc
    -0.14s  0.29%  0.19%     -0.14s  0.29%  runtime.nextFreeFast (inline)
    -0.12s  0.25% 0.063%     -0.30s  0.63%  runtime.sellock
    -0.11s  0.23%  0.29%     -0.13s  0.27%  runtime.(*mspan).writeHeapBitsSmall
     0.11s  0.23% 0.063%     -0.12s  0.25%  runtime.adjustframe
    -0.11s  0.23%  0.29%     -0.17s  0.36%  runtime.growslice
    -0.11s  0.23%  0.52%      0.15s  0.31%  runtime.unlock2
     0.10s  0.21%  0.31%      0.10s  0.21%  internal/runtime/syscall.Syscall6
    -0.10s  0.21%  0.52%     -0.23s  0.48%  runtime.pcvalue
    -0.09s  0.19%  0.71%     -0.09s  0.19%  internal/runtime/atomic.(*Uint32).CompareAndSwap (inline)
     0.09s  0.19%  0.52%      0.09s  0.19%  runtime.(*mspan).base (inline)
    -0.09s  0.19%  0.71%     -0.09s  0.19%  runtime.(*mspan).divideByElemSize (inline)
     0.09s  0.19%  0.52%      0.09s  0.19%  runtime.cheaprand (inline)
     0.09s  0.19%  0.33%      0.18s  0.38%  runtime.scanblock
     0.08s  0.17%  0.17%      0.12s  0.25%  go.etcd.io/etcd/api/v3/etcdserverpb.(*PutRequest).Unmarshal
    -0.08s  0.17%  0.33%     -0.08s  0.17%  internal/runtime/maps.ctrlGroup.matchH2
    -0.08s  0.17%   0.5%     -0.07s  0.15%  runtime.(*mLockProfile).recordUnlock

Nothing about maps. In fact, there's not a single sample in a map routine in the whole run at either commit. Which kinda sounds fishy, but would pprof lie?

mutexSampleContention is new and takes some time, although maybe not the 5% we're looking for. In the post profile, it appears only at 0.6%.

      flat  flat%   sum%        cum   cum%
     0.17s  0.35% 56.04%      0.29s   0.6%  runtime.mutexSampleContention (inline)

but maybe it is somehow related?

[randall77]

(I'm only running at GOMAXPROCS=20, maybe at GOMAXPROCS=88 it would get worse?)

[mknyszek]

Thanks for looking into it. I agree it's unlikely that maps are involved. I think this is more likely related to the mutex changes. The regression might be due to off-CPU time, which is a little hard to measure, given that these changes add correct mutex profile attribution to runtime.mutex. I'm also curious where the runtime.unlock calls are coming from -- what lock are we spending most of our time on?

It's not clear that we should necessarily do anything here even if so -- mainly I just wanted to create the issue to understand it and make a decision.

[mknyszek]

Looking at the changes again and paging everything back in, I am somewhat surprised there's a regression at all. Mutex profiling is off by default, and mutexSampleContention is essentially just a single atomic load and branch. Though, if a lock (especially if it's sched.lock, since we put that into a 'starvation is ok, low-latency' mode) is being hammered, it's possible. I will dig deeper.