basalt-26.3: roachtest: perturbation/full/splits/asleep=true failed

[cockroach-teamcity]

roachtest.perturbation/full/splits/asleep=true failed with artifacts on basalt-26.3 @ fafb48100baca554581cf9e1a6e33510d73fdc00:

Failed with:

(splits.go:317).startPerturbation: split splitperf_gn1s1_n2s1_n3s1.t batch 56: pq: replica unavailable: (n1,s1):1 unable to serve request to r547676:/Table/128/1/90{59813086853879904-61042853395239989} [(n1,s1):1, (n2,s3):2, (n3,s5):3, next=4, gen=152, sticky=9223372036.854775807,2147483647]: closed timestamp: 1790093846.996812266,0 (2026-09-22 16:17:26); raft status: {"id":"1","term":8,"vote":"1","commit":15,"lead":"0","leadEpoch":"0","raftState":"StatePreCandidate","applied":15,"progress":{},"leadtransferee":"0"}: have been waiting 63.00s for slow proposal ConditionalPut [/Local/Range/Table/128/1/9059813086853879904/RangeDescriptor], [txn: d87487ca]
test artifacts and logs in: /artifacts/perturbation/full/splits/asleep=true/run_1

Cluster Node to Ip Mapping:

Node	Public IP	Private IP
teamcity-21526551-1790056608-163-n13cpu16sm-0001		10.91.98.240
teamcity-21526551-1790056608-163-n13cpu16sm-0002		10.91.98.164
teamcity-21526551-1790056608-163-n13cpu16sm-0003		10.91.99.225
teamcity-21526551-1790056608-163-n13cpu16sm-0004		10.91.98.29
teamcity-21526551-1790056608-163-n13cpu16sm-0005		10.91.100.185
teamcity-21526551-1790056608-163-n13cpu16sm-0006		10.91.100.184
teamcity-21526551-1790056608-163-n13cpu16sm-0007		10.91.98.227
teamcity-21526551-1790056608-163-n13cpu16sm-0008		10.91.100.189
teamcity-21526551-1790056608-163-n13cpu16sm-0009		10.91.99.223
teamcity-21526551-1790056608-163-n13cpu16sm-0010		10.91.100.188
teamcity-21526551-1790056608-163-n13cpu16sm-0011		10.91.97.214
teamcity-21526551-1790056608-163-n13cpu16sm-0012		10.91.97.250
teamcity-21526551-1790056608-163-n13cpu16sm-0013		10.91.97.217

Parameters:

• acMode=defaultOption
• arch=amd64
• blockSize=4096
• cloud=gce
• coverageBuild=false
• cpu=16
• diskBandwidthLimit=0
• diskCount=2
• disks=2
• encrypted=false
• fillDuration=10m0s
• leaseType=leader
• mem=standard
• numNodes=12
• numWorkloadNodes=1
• perturbationDuration=10m0s
• ratioOfMax=0.5
• runtimeAssertionsBuild=false
• seed=0
• splits=500
• validationDuration=5m0s
• vcpu=16

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

Logs were not uploaded to Datadog

Same failure on other branches

• release-26.3.2-rc: roachtest: perturbation/full/splits/asleep=true failed #175589 release-26.3.2-rc: roachtest: perturbation/full/splits/asleep=true failed [A-kv C-bug C-test-failure O-roachtest O-robot P-3 T-kv X-duplicate branch-release-26.3.2-rc]
• release-26.3.1-rc: roachtest: perturbation/full/splits/asleep=true failed #173742 release-26.3.1-rc: roachtest: perturbation/full/splits/asleep=true failed [C-test-failure O-roachtest O-robot P-3 T-kv X-duplicate branch-release-26.3.1-rc]
• roachtest: perturbation/full/splits/asleep=true failed #171278 roachtest: perturbation/full/splits/asleep=true failed [C-bug C-test-failure O-roachtest O-robot P-3 T-kv branch-master]

/cc @cockroachlabs/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-68730

[angeladietz]

/investigate

[github-actions]

Investigation: perturbation/full/splits/asleep=true

Investigated failure: issue body / build 21526551
Failure SHA: fafb48100baca554581cf9e1a6e33510d73fdc00
Confidence: moderate-to-high on the causal chain; low on the ultimate trigger

What This Test Does

splits drives the cluster into an extreme replicas-per-vcpu state (600k splits ≈ 1.8M replicas on 12×16-vcpu nodes) and measures whether the foreground KV workload recovers afterwards. Stores are partitioned into 8 disjoint 3-store groups; each group owns one database whose voters are pinned to exactly those three stores, and splits are issued batch-by-batch against one table per group. asleep=true leaves store-liveness follower quiescence enabled so the bulk of the replica population is cheap.

Where the Failure Occurs

Batch 57 (0-indexed batch 56) of the split loop fails at
splits.go:317, which t.Fatals on the error returned by the per-group ALTER TABLE ... SPLIT AT at splits.go:293-294:

split splitperf_gn1s1_n2s1_n3s1.t batch 56: pq: replica unavailable: (n1,s1):1 unable to serve
request to r547676 ... raft status: {"term":8,"vote":"1","commit":15,"lead":"0","leadEpoch":"0",
"raftState":"StatePreCandidate","applied":15,"progress":{}} : have been waiting 63.00s for slow
proposal ConditionalPut [/Local/Range/.../RangeDescriptor]

The split's descriptor CPut stalled because r547676's n1 replica was leaderless and stuck in StatePreCandidate (lead=0, leadEpoch=0) — it campaigned twice (term 6 → 8) and never won. After 60s the replica circuit breaker tripped (replica_raft.go:1702). r547676 is not a random range: it was created 47 seconds earlier by batch 56 (new range lease ... term=6 at 16:16:44). Six sibling ranges from the same batch (r547671/2/4/5, r550640/1) tripped their breakers in the same 3-second window.

This is the test's own perturbation phase failing, not the post-perturbation validation.

Analysis

Hypothesis 1 (likely cause): a ~1s store-liveness support blip on n1 invalidated all ~47k leader leases on that node at once; the resulting election storm overflowed the raft send queues to n2/n3, dropping the pre-votes that newly-split ranges needed to elect a leader.

The chain is visible end-to-end in the logs:

1. 16:17:30.35 — n2's stores withdraw support for both of n1's stores and bump their epochs (withdrew support for store {NodeID:1 StoreID:1}; Epoch:2 → ...). n1 correspondingly logs lost support from store {...} for 40 of the 44 (store × store) pairs — i.e. n1's s1 and s2 lost store-liveness support from essentially every store in the cluster, simultaneously. All had the identical expiration 1790093850.331… (16:17:30.33), so they all came from the same heartbeat round.
2. 16:17:31.38 — support is re-established, ~1 second later, at a higher epoch. Under leader leases an epoch bump invalidates every leader lease fortified at the old epoch, so all ~47k leases on n1 (leases/node min=n9:45215 max=n4:48791 at batch 56) died at once and every one of those raft groups had to re-campaign and re-fortify.
3. 16:17:35 → 16:20:43 — raft send queue to n2/n3 is full fires continuously for 188 seconds on n1, and symmetrically on n2 and n3. The queue is a fixed 10,000-message channel and silently drops on overflow (raft_transport.go:854-863; the constant's own comment says "If the buffer fills up, we drop raft messages, so we'd be in trouble").
4. Dropped MsgPreVote/MsgVote traffic means elections can't complete. r547676 sat in StatePreCandidate for the whole window; n1's lease-acquisition rate collapsed from 50-100/s to ~1/s from 16:17:32 until 16:20:43, recovering exactly when the send queues drained.

Two details corroborate the mechanism:

• The congestion is confined to the n1↔n2 and n1↔n3 links. n4, n7 and n10 logged zero raft send queue is full messages. That is what the test's own pinning guarantees: groups 1 and 2 (stores 1/3/5 and 2/4/6) place every replica on n1, n2 or n3, so n1's ~280k replicas have their peers nowhere else. A lease/leader storm on n1 therefore concentrates entirely on two links.
• n1 is the node that blipped in both observed instances of this signature. The 2026-09-08 occurrence on master (#171278 comment) is byte-for-byte the same shape — StatePreCandidate, lead=0, leadEpoch=0, a batch-58 split, a range on the n1/n2/n3 triple. n1 is the SQL gateway for all 8 groups' split statements and also hosts system ranges, so it carries strictly more work than its peers.

Why n1's heartbeats lapsed is not established. Store liveness heartbeats go out every 1s with a 3s support duration (base/config.go:251-260), so n1 missed roughly three consecutive rounds. Ruled out: disk stall (no Pebble slow-sync or WAL-failover events on n1), GC (sub-ms STW pauses throughout), and OOM. What remains is scheduling/latency pressure: n1 was running at ~1430% of 1600% CPU (≈89%) steadily, and sendHeartbeats does a synchronous engine write on the same goroutine as the 1s ticker (support_manager.go:339-376). This matches miraradeva's earlier read on #171278: "a brief blip in store liveness sends the cluster in a frenzy… the initial blip seems to be some sort of scheduling latency."

A standing CPU tax worth flagging: CPU profiles from n1 both before (16:17:01) and during (16:17:41) the incident show Store.Descriptor — which walks every replica on the store via storeReplicaVisitor — consuming a steady ~9.5-9.9% of the whole 16-vcpu node, split roughly evenly between StoreGossip.GossipStore, Store.updateCapacityGauges, and MetricsRecorder.GenerateNodeStatus. At ~280k replicas per node these O(replicas) walks are a permanent ~1.5-core overhead that shrinks the headroom the store-liveness goroutine needs. Note this is baseline cost, identical before and during — so it is a contributing pressure, not the trigger.

Recommendations

• Product side. The interesting question is why a 1-second store-liveness blip costs 3 minutes of unavailability on the affected node. Two amplifiers look addressable: (a) a whole node's leader leases being invalidated by a single epoch bump produces an unthrottled ~47k-way election storm with no backoff; (b) the 10k raft send queue drops indiscriminately, so election traffic is lost to the very congestion the elections created — prioritising MsgPreVote/MsgVote/MsgHeartbeat over MsgApp when the queue is near-full would break the feedback loop. Worth confirming against RACv2/raft-transport owners whether either is already tracked.
• Test side. The test is doing exactly what it was designed to do — finding the density ceiling — but ~8,760 replicas/vcpu is where this cluster shape stops being stable. If the goal is a signal-producing nightly rather than a repeated report of the same tip-over, consider lowering targetSplits below the observed cliff (failure landed at batch 57/60, ~560k splits) as miraradeva already suggested on roachtest: perturbation/full/splits/asleep=true failed #171278.

Related Issues and PRs

• #171278 (master, open, 56 comments) — the umbrella issue for this test. Contains the same failure signature on 2026-09-08 (comment): StatePreCandidate, lead=0, leadEpoch=0, late batch, n1/n2/n3 triple. Same failure mode — this issue is effectively a basalt-26.3 recurrence of it.
• #171278 comment 2026-09-21 — miraradeva's diagnosis of the adjacent fetching span stats failures as the same store-liveness blip → overload cascade. That analysis and this one converge.
• #175589 (release-26.3.2-rc) and #173742 (release-26.3.1-rc) — both are the ValidateTokensReturned token-accounting failure mode, which miraradeva diagnosed as an artifact of the validation query cross-joining crdb_internal.node_metrics with itself. Different root cause; they are linked as "same failure on other branches" only by test name.

Timeline

All times UTC, 2026-09-22. Density at failure: 560,571 ranges ≈ 1.68M replicas ≈ 8,759 replicas/vcpu/node — the highest the run reached, and ~93% of the test's own 9,400 target.

Time	Event
16:16:44	r547676 created by batch 56's split; acquires leader lease at term 6
16:17:11	batch 56/60 done (560k/600k splits)
16:17:11-27	test's reportDensity (count(*) over 560k ranges) + reportBalance run on gateway n1
16:17:30.35	n2 (and every other store) withdraws store-liveness support for n1 s1/s2, bumping epochs
16:17:30.57	n1 logs lost support from store … × 40
16:17:31.38	support restored at higher epoch; all ~47k leader leases on n1 are now invalid
16:17:32.45	r547676's split CPut proposed (never applies)
16:17:35	raft send queue to n2/n3 is full begins on n1; mirrored on n2/n3
16:18:32-35	circuit breakers trip on r547671/2/4/5/6, r550640/1 — all batch-56 ranges
16:18:35	AdminSplit returns result is ambiguous, retries
16:20:43	raft send queues drain; lease acquisitions resume
16:20:35	test fails (errgroup WaitE returns)

No relevant commits to pkg/kv/kvserver/storeliveness/ or raft_transport.go in the recent history on this branch, so this does not look like a regression from a specific change — it reads as a density threshold being crossed.

Detailed evidence and investigation notes

Log Excerpts

Store liveness withdrawal, supporter side (n2, cockroach-kv-exec.log):

I260922 16:17:30.353819 [n2,s3] withdrew support for store {NodeID:1 StoreID:2}; old = {Epoch:1 Expiration:1790093850.342906391}, new = {Epoch:...
I260922 16:17:30.353854 [n2,s3] withdrew support for store {NodeID:1 StoreID:1}; old = {Epoch:2 Expiration:1790093850.331364924}, new = {Epoch:...
I260922 16:17:30.354537 [n2,s3] withdrew support from 2 stores
I260922 16:17:31.383887 [n2,s3] provided support for store {NodeID:1 StoreID:1}; old = {Epoch:3 Expiration:0,0}, new = {Epoch:3 Expiration:1790...

Requester side (n1) — all 22 peer stores lost in the same instant, identical prior expirations:

I260922 16:17:30.568018 [n1,s1] lost support from store {NodeID:12 StoreID:24}; old = {Epoch:1 Expiration:1790093850.331364924}
I260922 16:17:30.568512 [n1,s1] lost support from store {NodeID:2  StoreID:3};  old = {Epoch:2 Expiration:1790093850.331364924}
... (40 such lines, all at 16:17:30)

Send-queue saturation, confined to the n1/n2/n3 triple:

$ grep -c "raft send queue" node{1,2,3,4,7,10}/cockroach.log
node1: 181   node2: 160   node3: 149
node4:   0   node7:   0   node10:  0

(the log is rate-limited to 1/s, so 181 lines ≈ 181 s of continuous saturation, 16:17:35 → 16:20:43)

n1 lease-acquisition rate collapse (new range lease per second, cockroach-health.log):

16:16:23  72     16:17:29   7
16:16:24  94     16:17:30   4
16:16:25  73     16:17:31   1
16:17:04  59     16:17:32   1
16:17:05  72     16:17:58   1   <- ~1/s for the next 3 minutes
16:17:11  28     ...

Victim cohort — all batch-56 ranges, all on n1:

16:18:32.471 r547674/1 breaker: tripped
16:18:32.808 r547672/1 breaker: tripped
16:18:32.956 r547675/1 breaker: tripped
16:18:32.975 r547671/1 breaker: tripped
16:18:33.791 r550640/3 breaker: tripped
16:18:34.255 r550641/3 breaker: tripped
16:18:35.459 r547676/1 breaker: tripped   <- the one the test saw

Code References

• Raft send queue drops on overflow, 10k fixed capacity:
  raft_transport.go:43-53,
  raft_transport.go:854-863
• Store-liveness heartbeat loop, synchronous engine write on the ticker goroutine:
  support_manager.go:339-376
• Heartbeat interval 1s / support duration 3s:
  base/config.go:251-260
• Per-store voter pinning that concentrates all of n1's replica peers onto n2/n3:
  splits.go:414-446

CPU profile, n1 (10s samples)

Before the blip (16:17:01, 1398% of 1600%) and during it (16:17:41, 1443%):

                       16:17:01      16:17:41
raftScheduler worker      —           33.1%
Store.Descriptor         9.88%         9.50%     <- full replica walk, unchanged
  via GossipStore        33.5%        33.0%
  via updateCapacityGauges 33.4%      34.6%
  via GenerateNodeStatus 33.1%        32.4%
SQL connExecutor          —           17.3%

ASH for the same window is dominated by RaftProposalWait (7416 + 1856 + 1764 LEASE_ACQUISITION samples of 25168), i.e. everything is blocked behind raft, not burning CPU.

Things Ruled Out

• Disk stall / WAL problem on n1. No failover, slow sync, or disk-stall entries in n1's Pebble log covering 16:15-16:20. IO admission control reported admitting all with L0 compaction score ~0.00 throughout. --wal-failover=among-stores is configured but never engaged.
• Go GC pause. gctrace shows steady ~2.6s concurrent mark with sub-millisecond STW pauses (0.6+2675+0.33 ms) across the incident; no outlier at gc 500/501.
• OOM / memory pressure. RSS steady at 38-43 GiB of 60 GiB; heap well under the 34 GiB soft limit. n1 dmesg is clean.
• A cluster-wide event. Only n1 lost store-liveness support (n3 lost exactly one peer, n2 and n4 lost none). Nodes 4/7/10 show no raft congestion at all.
• The test's own diagnostic queries as the trigger. reportDensity/reportBalance are genuinely expensive (a 560k-row meta2 scan plus an uncached store-descriptor walk) and had just run at 16:17:11-27, but the Store.Descriptor CPU share is identical before and during the incident, and the blip lands 3s after the queries complete. They add pressure; they don't explain the timing.
• A recent code regression. git log shows no changes to pkg/kv/kvserver/storeliveness/ or raft_transport.go in the relevant window on this branch.

Other Failure Occurrences

This issue thread has only one failure (the issue body). Comparing across the linked threads:

Issue	Branch	Signature	Same mode?
175769 (this)	basalt-26.3	StatePreCandidate leaderless split, batch 56	—
#171278 2026-09-08	master	StatePreCandidate leaderless split, batch 58	Yes — same triple, same raft state
#171278 various	master	fetching span stats during SHOW RANGES	Likely same underlying cascade, different victim
#171278 various	master	ValidateTokensReturned token leak	No — validation-query artifact, diagnosed
#175589	release-26.3.2-rc	ValidateTokensReturned	No
#173742	release-26.3.1-rc	ValidateTokensReturned	No

Tooling Feedback

• tsdump2duck could not be built. go build ./pkg/cmd/tsdump2duck fails because pkg/storage imports github.com/cockroachdb/pebble-private, which the sandbox's git credentials cannot fetch (could not read Username for 'https://github.com'). This blocked the entire timeseries-metrics workflow documented in the prompt, which would have been the fastest way to quantify raft.transport.sends-dropped, storeliveness.support_withdraw.*, and raft.scheduler.latency across all 12 nodes instead of inferring rates from rate-limited log lines. A prebuilt tsdump2duck binary, a vendored module cache, or credentials for the private module would make this available.
• unzip -j into a directory per node is awkward for a 450 MB archive with per-node rotated logs; several shell forms (for loops, $var expansion in some positions, process substitution, subshells) are rejected by the sandbox, so each node's log had to be extracted in a separate tool call.
• The debug.zip was not downloaded (the artifacts.zip logs were sufficient), so cluster-level views like crdb_internal.kv_store_status snapshots at failure time were not consulted.

Workflow run

---

Was this investigation helpful? Leave a 👍 or 👎 on this comment.

---

Generated by claude-opus-5 at high effort. Use /investigate fable-5-1 max to go deeper.

Workflow run · Was this investigation helpful? Leave a 👍 or 👎 on this comment.

[angeladietz]

looks like a flake, removing release-blocker