roachperf: kv95 and kv0 regression around October 28th

[erikgrinaker]

Some versions of kv95 and kv0 saw a ~10% performance regression around October 28th, e.g. kv95/enc=false/nodes=1/cpu=32:

This is even more pronounced with 64KB payloads, e.g. kv95/enc=false/nodes=3/cpu=32/size=64kb:

Admission control was enabled by default in #68535, which merged on October 28th, so that seems like a likely culprit. Running a couple of benchmarks to confirm.

[erikgrinaker]

Confirmed, comparing 3207354 (admission control disabled) with 7e5741b (admission control enabled) shows a ~20% ops/sec regression on kv95/enc=false/nodes=3/cpu=32/size=64kb:

name                                     old ops/sec  new ops/sec  delta
kv95/enc=false/nodes=3/cpu=32/size=64kb   11.0k ± 1%    8.6k ± 2%  -21.82%  (p=0.000 n=10+10)

name                                     old p50      new p50      delta
kv95/enc=false/nodes=3/cpu=32/size=64kb    2.80 ± 0%    1.50 ± 0%  -46.43%  (p=0.001 n=7+7)

name                                     old p95      new p95      delta
kv95/enc=false/nodes=3/cpu=32/size=64kb    35.7 ± 0%    36.7 ± 8%     ~     (p=0.137 n=8+10)

name                                     old p99      new p99      delta
kv95/enc=false/nodes=3/cpu=32/size=64kb     419 ± 0%     481 ± 2%  +14.67%  (p=0.000 n=8+9)

@sumeerbhola Is this regression expected and accepted with admission control?

[tbg]

cc @sumeerbhola

[sumeerbhola]

The regression should only be for cases where the LSM was degrading prior to admission control (admission control is not expected to reduce throughput if the bottleneck was CPU). If one clicks to get details of a run, and sees something like the following where the rate fluctuates, it is because for LSM overload the tokens get adjusted every 15s (unhealthy for 15s, so fewer tokens, resulting in transition to healthy, with unconstrained tokens, and then repeat). Admission control will only affect writes in this case but since we are issuing a sequence of reads and writes from the same workers, reducing write throughput also reduces read throughput.

The corresponding no-admission roachtest has a higher mean rate, but note the decline in rate over time as the LSM becomes more and more unhealthy. It is not a sustainable rate, but since we only run for 10min we have overlooked this problem.

You should see the same thing with the kv0 slowdowns.

But this is not the case with kv95/enc=false/nodes=1/cpu=32, and kv95 typically needs to have larger block sizes to cause write overload, which makes me suspicious that it could be a different root cause. We didn't have an "admission" variant for this test prior to the enabling of admission control, but we did have it for kv95/enc=false/nodes=3/cpu=32. See the screenshots below for the with and without admission for a randomly picked day (Oct 17) -- they are close:

[erikgrinaker]

The corresponding no-admission roachtest has a higher mean rate, but note the decline in rate over time as the LSM becomes more and more unhealthy. It is not a sustainable rate, but since we only run for 10min we have overlooked this problem.

Interesting find. This seems fine then, since presumably running for another 10 minutes could have shown an overall improvement when admission control is enabled.

But this is not the case with kv95/enc=false/nodes=1/cpu=32, and kv95 typically needs to have larger block sizes to cause write overload, which makes me suspicious that it could be a different root cause.

Interesting, I'll run another bisection and see if something turns up. Thanks!

[tbg]

In light of this, should we consider running these perf tests for longer than ten minutes (say thirty minutes)? This will completely shift the graphs we see (since they use total qps or something like that) but it may give us better data in the long run?

[erikgrinaker]

Yeah, 30 minutes makes sense. That probably shouldn't be the default though, since people will run these from the command-line as well, but for the nightlies that seems reasonable.

I'll submit a PR.

[tbg]

Yeah, 30 minutes makes sense. That probably shouldn't be the default though, since people will run these from the command-line as well, but for the nightlies that seems reasonable. I'll submit a PR.

Thanks! You don't think that approach will be confusing to people trying to repro the numbers? I would've thought 30m is the default but it should be "easy" to lower that to 10 minutes when desired, perhaps through an env var (I know you love those!) or small code change (but code change sucks for bisecting).

[erikgrinaker]

OK, we can make 30 the default.

[erikgrinaker]

#72646

[erikgrinaker]

Bisected to bba05aa.

@ajwerner Looks like #71936 caused a ~10% hit on kv95/enc=false/nodes=1/cpu=32 and other benchmarks.

[ajwerner]

wowza, ack, okay

[ajwerner]

I've been benchmarking and tuning this. Indeed #71936 caused a good bit of the pain. However, I don't think it was all 10%, I think it was closer to 7% and then another bit was cause by admission control. I went and tuned the catalog layer more in #72740 such that I think it makes up for both, but I see that the admission control code now shows up prominently in the mutex profile.

Turning off admission control seems to show about a 3-4% improvement in that benchmark. My guess is that we should be running that benchmark at a higher concurrency, at which point I suspect it’d show more. I've run the benchmark with admission control off and on with the patch in #72740 and the results are around 103893.2 vs 99933.6 for total throughput.

[sumeerbhola]

@ajwerner thanks for investigating.
What time interval was the mutex profile taken over? And do you know what the cpu utilization value was? It is very possible that contention is dropping cpu utilization peak by a few percent, given that the KV benchmark has tiny work units being subject to admission, similar to the observation in #65614 (comment)

[ajwerner]

@ajwerner thanks for investigating. What time interval was the mutex profile taken over? And do you know what the cpu utilization value was? It is very possible that contention is dropping cpu utilization peak by a few percent, given that the KV benchmark has tiny work units being subject to admission, similar to the observation in #65614 (comment)

I think the mutex profile covers time since the process started, though I could be wrong. It was probably around a minute into the benchmark run. I wasn't running it for that long. I'm setting it back up now.

---

Turning off admission control had only a very modest impact on CPU utilization. There was an initial throughput bump, but interestingly, it didn't last long. Tail latency went down and stayed down, but from a small number. I turned off admission control at 23:29.

[ajwerner]

The above were run at --concurrency 96 with 1000 splits. 96 is probably too many. The original experiment was 64 and this one was at 64. There was a regime change I don't understand which happened with admission control after 23:41. Then another when I turned it off at 23:42.

I then turned it back on around 23:47, and saw the throughput fall again. The CPU utilization fell a tad, from ~97.4% to ~96.2%.

[sumeerbhola]

With that low number of runnable goroutines, there should be no queueing in admission control (the admission control page in the db console should confirm that), so any affect would be the contention due to acquiring the mutexes WorkQueue.admitMu, WorkQueue.mu, GrantCoordinator.mu. The first one would be contended.

[tbg]

I think the mutex profile covers time since the process started, though I could be wrong. It was probably around a minute into the benchmark run. I wasn't running it for that long. I'm setting it back up now.

Just a drive-by to mention that to the best of my knowledge, on recent Go versions the mutex profile supports the ?seconds=5s thing as well.

[sumeerbhola]

@ajwerner if admission control is not decreasing cpu utilization, and we are seeing a 3-4% decline in throughput, the admission control code should be showing up as significant in the cpu profile -- do you have one?

[ajwerner]

profile_without.pb.gz
profile_with.pb.gz

https://share.polarsignals.com/c7ecb30/ -- is with.

I have the binary if you want it to get line info. Looks like admission control is ~1% of CPU samples. It does look like some of the samples are in _doSpin/procYield on mutexes.