roachtest: rebalance/by-load/replicas failed

[cockroach-teamcity]

roachtest.rebalance/by-load/replicas failed with artifacts on master @ e4fcae1625a35917d08a2a569d24529b0cc089d2:

The test failed on branch=master, cloud=gce:
test artifacts and logs in: /artifacts/rebalance/by-load/replicas/run_1
	rebalance_load.go:128,rebalance_load.go:155,test_runner.go:875: timed out before leases were evenly spread

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-14583

[nvanbenschoten]

12:26:56 rebalance_load.go:191: not all nodes have a lease yet: [s4: 1, s5: 1, s6: 4]
12:27:01 rebalance_load.go:191: not all nodes have a lease yet: [s4: 1, s5: 1, s6: 4]
...
12:31:51 rebalance_load.go:191: not all nodes have a lease yet: [s2: 1, s3: 1, s4: 1, s5: 2, s6: 1]
12:31:56 rebalance_load.go:191: not all nodes have a lease yet: [s2: 1, s3: 1, s4: 1, s5: 2, s6: 1]
12:32:01 test_impl.go:312: test failure: 	rebalance_load.go:128,rebalance_load.go:155,test_runner.go:875: timed out before leases were evenly spread

Over the course of 5 minutes, the leases on this table fail to make their way to store 1.

We have high-verbosity logging enabled and can see why store 5 is not transferring leases away:

I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078  ShouldTransferLease (lease-holder=5):
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  candidate: avg-ranges=39.333333333333336 avg-leases=8.333333333333332 avg-disk-usage=10 MiB avg-queries-per-second=4180.5905469332265›
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  3: ranges=39 leases=8 disk-usage=2.3 MiB queries-per-second=4171.06 l0-sublevels=0›
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  1: ranges=38 leases=8 disk-usage=972 KiB queries-per-second=11.51 l0-sublevels=0›
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  4: ranges=40 leases=7 disk-usage=19 MiB queries-per-second=4166.16 l0-sublevels=0›
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  6: ranges=39 leases=8 disk-usage=18 MiB queries-per-second=3993.85 l0-sublevels=0›
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  5: ranges=40 leases=10 disk-usage=18 MiB queries-per-second=8552.84 l0-sublevels=0›
I220331 12:31:59.544492 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1813 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1078 +‹  2: ranges=40 leases=9 disk-usage=2.6 MiB queries-per-second=4188.13 l0-sublevels=0›
I220331 12:31:59.544600 1272396 kv/kvserver/pkg/kv/kvserver/allocator.go:1843 ⋮ [n5,replicate,s5,r37/2:‹/Table/4{1-2}›] 1079  ShouldTransferLease decision (lease-holder=5): false

1: ranges=38 leases=8 disk-usage=972 KiB queries-per-second=11.51
...
5: ranges=40 leases=10 disk-usage=18 MiB queries-per-second=8552.84
...
ShouldTransferLease decision (lease-holder=5): false

This is surprising to me.

[aayushshah15]

This is surprising to me.

I think that's expected because it's the replicate queue's output, which only considers lease counts.

---

Looking at the logs, we see that the store-rebalancer does detect the expected rebalance opportunity.

kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:732 ⋮ [n5,s5,store-rebalancer] 812 rebalancing voter (qps=4105.78) for r47 on n5,s5 to n1,s1 in order to improve QPS balance

Then, this is what we see with that rebalance:

kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:395 ⋮ [n5,s5,store-rebalancer] 831 unable to relocate range to [n1,s1 n6,s6 n4,s4]: while carrying out changes [{ADD_VOTER n1,s1} {REMOVE_VOTER n5,s5}]: removing learners from r47:‹/Table/106/1/-{6148914691236517888-3074457345618258944}› [(n4,s4):1, (n6,s6):4, (n5,s5):7LEARNER, (n1,s1):8, next=9, gen=32, sticky=9223372036.854775807,2147483647]: change replicas of r47 failed: descriptor changed: [expected] r47:‹/Table/106/1/-{6148914691236517888-3074457345618258944}› [(n4,s4):1, (n6,s6):4, (n5,s5):7LEARNER, (n1,s1):8, next=9, gen=32, sticky=9223372036.854775807,2147483647] != [actual] r47:‹/Table/106/1/-{6148914691236517888-3074457345618258944}› [(n4,s4):1, (n6,s6):4, (n1,s1):8, next=9, gen=33, sticky=9223372036.854775807,2147483647]

The rebalance technically succeeded but the AdminRelocateRange call failed with an error due to the LEARNER replica getting cleared up.

When this AdminRelocateRange call fails, the StoreRebalancer assumes that the replica did not actually move and does not change its in-memory account of its QPS. This means that it will try moving more replicas away than it should. We see this in the test where s5 has two hot ranges, and s5 tries rebalancing both of them away redundantly. Both of these rebalances failed for the same reason.

rebalancing r46 (4140.25 qps) to better balance load: voters from (n4,s4):1,(n5,s5):7,(n6,s6):4 to [n1,s1 n4,s4 n6,s6];
...
rebalancing r47 (4105.78 qps) to better balance load: voters from (n4,s4):1,(n6,s6):4,(n5,s5):7 to [n1,s1 n6,s6 n4,s4]; 

I think we could:

1. Not return an error from AdminChangeReplicas when it's at the last step of removing the demoted learner replica and it finds that the learner has already been removed.
2. In the store-rebalancer, when an AdminRelocateRange call errors out, we should be re-reading the range's descriptor afresh to determine whether we actually moved any replicas.
3. We should implement the approach mentioned in this comment, to make these races more unlikely: kvserver: merge queue racing against replicate queue #57129 (comment)

[nvanbenschoten]

All three of your suggestions sound beneficial. Of them, the first sounds the most straightforward and least risky. It may be small enough to slip into a 22.1 point release.

How do you feel about removing the release blocker label from this issue and opening two new "quick win" issues for the first two items?

[nvanbenschoten]

We should implement the approach mentioned in this comment, to make these races more unlikely

Was there enough in the logs to determine who was racing with the StoreRebalancer?

[aayushshah15]

Closed by 466f42c