roachtest: rebalance/by-load/replicas/mixed-version failed

[cockroach-teamcity]

Note: This build has runtime assertions enabled. If the same failure was hit in a run without assertions enabled, there should be a similar failure without this message. If there isn't one, then this failure is likely due to an assertion violation or (assertion) timeout.

roachtest.rebalance/by-load/replicas/mixed-version failed with artifacts on release-24.3 @ dc6fad057934c7487be4baefb75eea651e4da71a:

(mixedversion.go:791).Run: mixed-version test failure while running step 36 (run "rebalance load run"): CPU not evenly balanced after timeout: within bounds mean=80.0 tolerance=20.0% (±16.0) bounds=[64.0, 96.1]
	stores=[s1: 75 (-5.3%), s2: 77 (-3.0%), s3: 72 (-9.3%), s4: 95 (+19.5%), s5: 78 (-2.1%), s6: 80 (+0.2%)]
test artifacts and logs in: /artifacts/rebalance/by-load/replicas/mixed-version/run_1

Parameters:

• arch=amd64
• cloud=gce
• coverageBuild=false
• cpu=4
• encrypted=false
• fs=ext4
• localSSD=true
• mvtDeploymentMode=system-only
• mvtVersions=v23.2.25 → v24.1.18 → release-24.3
• runtimeAssertionsBuild=true
• ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

Same failure on other branches

• roachtest: rebalance/by-load/replicas/mixed-version failed #147284 roachtest: rebalance/by-load/replicas/mixed-version failed [B-runtime-assertions-enabled C-test-failure O-roachtest O-robot T-kv X-duplicate branch-master]

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-51079

[stevendanna]

Removing release blocker, but this does look potentially legit. s4 stayed at 90+% CPU through most of the test.

[tbg]

From the looks of it, there's something off with the cpu-per-second vs reality. s4 considers itself at ~572ms/s (half a core) and thinks the cluster averages 556ms/sec (just slightly less). But really s4 is way above what the cluster is doing.

I250529 12:19:59.902432 312 13@kv/kvserver/store_rebalancer.go:499 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 236 considering load-based lease transfers for s4 with (queries-per-second=3081.3 cpu-per-second=572ms) load, mean=(queries-per-second=4389.1 cpu-per-second=505ms), upperThreshold=(queries-per-second=4389.1 cpu-per-second=556ms)
I250529 12:19:59.902960 312 13@kv/kvserver/store_rebalancer.go:639 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 237 ran out of leases worth transferring and load (queries-per-second=3081.3 cpu-per-second=572ms) is still above desired threshold (queries-per-second=4389.1 cpu-per-second=556ms); considering load-based replica rebalances
I250529 12:19:59.903514 312 13@kv/kvserver/store_rebalancer.go:654 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 238 ran out of replicas worth transferring and load (queries-per-second=3081.3 cpu-per-second=572ms) is still above desired threshold (queries-per-second=4389.1 cpu-per-second=556ms); will check again soon
I250529 12:19:59.903724 312 13@kv/kvserver/store_rebalancer.go:281 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 239 1: r488:‹/Table/119/1/{307445734561825852-614891469123651712}› replicas=[(n1,s1):5,(n2,s2):4,(n4,s4):3] load=[batches/s=444.7 request_cpu/s=55ms raft_cpu/s=7ms write(keys)/s=22.4 write(bytes)/s=1.0 KiB read(keys)/s=446.2 read(bytes)/s=4.2 KiB]
I250529 12:19:59.903724 312 13@kv/kvserver/store_rebalancer.go:281 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 239 + 2: r511:‹/Table/119/1/-6{456360425798343068-148914691236517208}› replicas=[(n3,s3):1,(n2,s2):2,(n4,s4):3] load=[batches/s=427.5 request_cpu/s=55ms raft_cpu/s=7ms write(keys)/s=21.7 write(bytes)/s=997 B read(keys)/s=427.5 read(bytes)/s=4.0 KiB]
I250529 12:19:59.903724 312 13@kv/kvserver/store_rebalancer.go:281 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 239 + 3: r479:‹/Table/119/1/-5{534023222112865488-226577487551039628}› replicas=[(n3,s3):1,(n1,s1):4,(n4,s4):3] load=[batches/s=442.2 request_cpu/s=54ms raft_cpu/s=7ms write(keys)/s=22.5 write(bytes)/s=1.0 KiB read(keys)/s=446.8 read(bytes)/s=4.3 KiB]
I250529 12:19:59.903724 312 13@kv/kvserver/store_rebalancer.go:281 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 239 + 4: r538:‹/Table/119/1/{6763806160360168912-7071251894921994772}› replicas=[(n3,s3):1,(n6,s6):2,(n4,s4):3] load=[batches/s=449.8 request_cpu/s=54ms raft_cpu/s=7ms write(keys)/s=22.1 write(bytes)/s=1019 B read(keys)/s=455.5 read(bytes)/s=4.4 KiB]
I250529 12:19:59.903724 312 13@kv/kvserver/store_rebalancer.go:281 ⋮ [T1,Vsystem,n4,s4,store-rebalancer,obj=‹cpu›] 239 + 5: r539:‹/Table/119/1/6{148914691236517192-456360425798343052}› replicas=[(n3,s3):1,(n6,s6):2,(n4,s4):3] load=[batches/s=446.3 request_cpu/s=54ms raft_cpu/s=7ms write(keys)/s=22.1 write(bytes)/s=1019 B read(keys)/s=450.5 read(bytes)/s=4.3 KiB]

Let's assume that the store rebalancer is right. Maybe the imbalance is not caused by replicas?
There's no current cpu profile, but there's one from closer to the beginning of the test, and indeed CPU usage is not really driven by "replica stuff" at all. So perhaps the workload "just" ended up fairly imbalanced?