roachtest: splits/load/sequential/nodes=3 failed

[cockroach-teamcity]

roachtest.splits/load/sequential/nodes=3 failed with artifacts on release-23.2 @ 1a497ceea8c72d2a853404a9c5a0020f7509fadf:

(monitor.go:153).Wait: monitor failure: 3 splits, expected between 0 and 2 splits (ranges 4 initial 1)
test artifacts and logs in: /artifacts/splits/load/sequential/nodes=3/run_1

Parameters:

• ROACHTEST_arch=amd64
• ROACHTEST_cloud=gce
• ROACHTEST_coverageBuild=false
• ROACHTEST_cpu=4
• ROACHTEST_encrypted=false
• ROACHTEST_metamorphicBuild=false
• ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-35741

[kvoli]

I'll take a look at this.

[kvoli]

The three QPS load splits due to the workload not being perfectly sequential between concurrent kv worker threads with different request latency. The split key has around 100 samples in comparison to other keys that are in the reservoir -- which adds up how there could be multiple splits if sampling is unlucky.

I'm closing this as a test issue which is probably quite rare. We could update the workload to be truly sequential, or assert on a larger of upper bound.

split 1

I240130 07:07:34.780898 110280 13@kv/kvserver/split/decider.go:261 ⋮ [T1,Vsystem,n1,s1,r68/1:‹/{Table/106-Max}›] 1214  suggesting split key /Table/106/1/‹151185›/‹0› splitter_state=objective=‹qps› count=4291 suggestions=0 last=11166.4 last-roll=2024-01-30 07:07:34.383760019 +0000 UTC m=+37.410201058 last-suggest=0001-01-01 00:00:00 +0000 UTC key=/Table/106/1/‹151185›/‹0› start=2024-01-30 07:07:14.35447488 +0000 UTC m=+17.380915920 count=112125 samples=[/Table/106/1/‹40876›/‹0›(l=282 r=110271 c=0) /Table/106/1/‹41860›/‹0›(l=272 r=109296 c=0) /Table/106/1/‹151185›/‹0›(l=45 r=55 c=0) /Table/106/1/‹52131›/‹0›(l=253 r=99061 c=0) /Table/106/1/‹131143›/‹0›(l=69 r=20085 c=0) /Table/106/1/‹140756›/‹0›(l=38 r=10471 c=0) /Table/106/1/‹108360›/‹0›(l=101 r=42846 c=0) /Table/106/1/‹144704›/‹0›(l=17 r=6517 c=0) /Table/106/1/‹59439›/‹0›(l=228 r=91766 c=0) /Table/106/1/‹59630›/‹0›(l=227 r=91573 c=0) /Table/106/1/‹68157›/‹0›(l=202 r=83055 c=0) /Table/106/1/‹69758›/‹0›(l=193 r=81391 c=0) /Table/106/1/‹102091›/‹0›(l=118 r=49129 c=0) /Table/106/1/‹76177›/‹0›(l=216 r=75043 c=0) /Table/106/1/‹76894›/‹0›(l=183 r=74321 c=0) /Table/106/1/‹104719›/‹0›(l=112 r=46503 c=0) /Table/106/1/‹110952›/‹0›(l=112 r=40280 c=0) /Table/106/1/‹86405›/‹0›(l=161 r=64817 c=0) /Table/106/1/‹111582›/‹0›(l=97 r=39630 c=0) /Table/106/1/‹90038›/‹0›(l=152 r=61182 c=0)]

split 2

I240130 07:07:46.243610 154028 13@kv/kvserver/split/decider.go:261 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/{Table/106/1/…-Max}›] 1223  suggesting split key /Table/106/1/‹215215›/‹0› splitter_state=objective=‹qps› count=4461 suggestions=0 last=11460.9 last-roll=2024-01-30 07:07:45.849783702 +0000 UTC m=+48.876224741 last-suggest=0001-01-01 00:00:00 +0000 UTC key=/Table/106/1/‹215215›/‹0› start=2024-01-30 07:07:35.840450434 +0000 UTC m=+38.866891486 count=59230 samples=[/Table/106/1/‹157278›/‹0›(l=167 r=57917 c=0) /Table/106/1/‹160650›/‹0›(l=155 r=54575 c=0) /Table/106/1/‹161536›/‹0›(l=126 r=53672 c=0) /Table/106/1/‹163991›/‹0›(l=126 r=51242 c=0) /Table/106/1/‹164101›/‹0›(l=130 r=51121 c=0) /Table/106/1/‹173188›/‹0›(l=103 r=42061 c=0) /Table/106/1/‹175200›/‹0›(l=98 r=40048 c=0) /Table/106/1/‹179051›/‹0›(l=85 r=36163 c=0) /Table/106/1/‹186189›/‹0›(l=74 r=29072 c=0) /Table/106/1/‹215215›/‹0›(l=40 r=60 c=0) /Table/106/1/‹191035›/‹0›(l=72 r=24218 c=0) /Table/106/1/‹191239›/‹0›(l=76 r=24024 c=0) /Table/106/1/‹191765›/‹0›(l=54 r=23474 c=0) /Table/106/1/‹192536›/‹0›(l=57 r=22706 c=0) /Table/106/1/‹200635›/‹0›(l=66 r=14634 c=0) /Table/106/1/‹204147›/‹0›(l=49 r=11122 c=0) /Table/106/1/‹204304›/‹0›(l=27 r=10934 c=0) /Table/106/1/‹206725›/‹0›(l=24 r=8540 c=0) /Table/106/1/‹207624›/‹0›(l=28 r=7623 c=0) /Table/106/1/‹212170›/‹0›(l=15 r=3105 c=0)]

split 3

I240130 07:08:00.383858 6438 13@kv/kvserver/split/decider.go:261 ⋮ [T1,Vsystem,n1,s1,r70/1:‹/{Table/106/1/…-Max}›] 1238  suggesting split key /Table/106/1/‹292832›/‹0› splitter_state=objective=‹qps› count=729 suggestions=0 last=9059.1 last-roll=2024-01-30 07:08:00.297432899 +0000 UTC m=+63.323873943 last-suggest=0001-01-01 00:00:00 +0000 UTC key=/Table/106/1/‹292832›/‹0› start=2024-01-30 07:07:47.281328986 +0000 UTC m=+50.307770027 count=71818 samples=[/Table/106/1/‹283081›/‹0›(l=28 r=9790 c=0) /Table/106/1/‹225558›/‹0›(l=168 r=67258 c=0) /Table/106/1/‹226892›/‹0›(l=170 r=65934 c=0) /Table/106/1/‹292832›/‹0›(l=50 r=50 c=0) /Table/106/1/‹282696›/‹0›(l=44 r=10180 c=0) /Table/106/1/‹278174›/‹0›(l=57 r=14701 c=0) /Table/106/1/‹235273›/‹0›(l=176 r=57578 c=0) /Table/106/1/‹292070›/‹0›(l=11 r=795 c=0) /Table/106/1/‹239217›/‹0›(l=149 r=53633 c=0) /Table/106/1/‹243971›/‹0›(l=129 r=48882 c=0) /Table/106/1/‹246390›/‹0›(l=126 r=46470 c=0) /Table/106/1/‹291622›/‹0›(l=4 r=1251 c=0) /Table/106/1/‹250848›/‹0›(l=142 r=42016 c=0) /Table/106/1/‹258356›/‹0›(l=90 r=34492 c=0) /Table/106/1/‹261049›/‹0›(l=93 r=31816 c=0) /Table/106/1/‹286092›/‹0›(l=40 r=6779 c=0) /Table/106/1/‹266297›/‹0›(l=64 r=26551 c=0) /Table/106/1/‹266345›/‹0›(l=77 r=26520 c=0) /Table/106/1/‹270158›/‹0›(l=59 r=22702 c=0) /Table/106/1/‹274320›/‹0›(l=70 r=18555 c=0)]