roachtest: admission-control/multitenant-fairness/read-heavy/even/cpu-time-tokens failed

[cockroach-teamcity]

roachtest.admission-control/multitenant-fairness/read-heavy/even/cpu-time-tokens failed with artifacts on master @ c2092a4f50acf5bb543d16c1b3e7673e7f2ad0e5:

Failed with:

(assertions.go:387).Fail: 
	Error Trace:	pkg/cmd/roachtest/tests/admission_control_multitenant_fairness.go:365
	            				pkg/cmd/roachtest/tests/admission_control_multitenant_fairness.go:124
	            				pkg/cmd/roachtest/test_runner.go:1561
	            				src/runtime/asm_amd64.s:1771
	Error:      	Received unexpected error:
	            	dial tcp 34.26.152.33:29000: connect: connection refused
	Test:       	admission-control/multitenant-fairness/read-heavy/even/cpu-time-tokens
(require.go:1401).NoError: FailNow called
test artifacts and logs in: /artifacts/admission-control/multitenant-fairness/read-heavy/even/cpu-time-tokens/run_1

Cluster Node to Ip Mapping:

Node	Public IP	Private IP
teamcity-21366086-1780134834-06-n5cpu4-0001	35.237.14.143	10.142.3.208
teamcity-21366086-1780134834-06-n5cpu4-0002	34.26.152.33	10.142.3.253
teamcity-21366086-1780134834-06-n5cpu4-0003	34.139.58.206	10.142.3.254
teamcity-21366086-1780134834-06-n5cpu4-0004	34.24.128.251	10.142.3.237
teamcity-21366086-1780134834-06-n5cpu4-0005	35.227.31.228	10.142.3.252

Parameters:

• arch=amd64
• cloud=gce
• coverageBuild=false
• cpu=4
• diskCount=0
• encrypted=false
• fs=ext4
• localSSD=true
• metamorphicLeases=default
• runtimeAssertionsBuild=false

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

See: Datadog Logs

/cc @cockroachdb/admission-control

This test on roachdash | Improve this report!

Jira issue: CRDB-64392

[stevendanna]

Feel free to pass back to me. But we should look into this. From first glance, it looks like one of the tenants shut itself down because its liveness lease was lost, which implies that it did get starved out.

[wenyihu6]

/investigate

[github-actions]

Investigation: admission-control/multitenant-fairness/read-heavy/even/cpu-time-tokens

Investigated failure: Issue body
Failure SHA: c2092a4f50acf5bb543d16c1b3e7673e7f2ad0e5
Confidence: high

What This Test Does

This roachtest sets up a single-node KV cluster (node 1) with 4 separate virtual cluster (tenant) pods running on nodes 2–5, each on 4-vCPU machines. The cpu-time-tokens variant drives 3,500 concurrent connections per tenant (vs. 250 in the base variant) to push CPU utilization into the range where admission control actively queues requests, exercising inter-tenant CPU fairness. The test enables admission.cpu_time_tokens.enabled, runs 20-minute KV workloads, verifies CPU utilization stayed between 70–90%, and then queries statement_statistics to compare throughput/latency fairness across tenants.

Where the Failure Occurs

The test fails at admission_control_multitenant_fairness.go:365 when attempting to connect to the virtual cluster on node 2 (app-fairness-n2) to run USE kv:

dial tcp 34.26.152.33:29000: connect: connection refused

The connection is refused because the tenant SQL process on node 2 has already shut itself down.

Analysis

Hypothesis: The tenant on node 2 was starved by the workload, causing its SQL liveness heartbeat to fail, which triggered a spontaneous shutdown.

Confidence: high

The evidence for this is strong and multi-layered:

1. Sqlliveness session deletion → spontaneous shutdown. The tenant logs on node 2 show at 10:27:12:

   • exiting heartbeat loop with error: session record deleted (slinstance.go:324)
   • server requesting spontaneous shutdown: sql liveness session deleted (start.go:893)
   • server shutdown without a prior graceful drain (server_sql.go:1860)

2. Extreme resource pressure on node 2. The tenant was under severe load:

   • At 10:10 (pre-workload): 1.0 GiB RSS, 485 goroutines, 14.1% CPU
   • At 10:25 (during workload): 6.0 GiB RSS, 23,426 goroutines, 33.1% CPU user
   • At 10:27:07 (just before crash): 7.2 GiB RSS, 23,192 goroutines, 140.2% CPU user, 22.2% CPU sys — a massive CPU spike on a 4-vCPU machine

3. Severe RPC latency on the KV node. RPCs to the KV node (n1) were taking 15–21 seconds during this period, as shown by slow replica RPC warnings. The KV node itself was saturated at 300–320% CPU user across its 4 vCPUs, and its RSS was 6.5–6.9 GiB.

4. The heartbeat was unable to extend the session in time. With RPCs taking 15+ seconds and the SQL liveness TTL being ~40 seconds by default, the session expired before the heartbeat could renew it. When the heartbeat attempted to extend the session and found the record deleted (slinstance.go:376–381), the clearSession handler returned false (indicating it wants to shut down rather than create a new session), triggering the "session record deleted" error.

5. The workloads still completed despite the tenant crash. The test log shows all four workloads completed at 10:36:54, and CPU utilization verification passed (82.45%). The crash happened at 10:27:14, ~10 minutes into the 20-minute workload. The workload on node 2 was configured with --tolerate-errors, so it continued despite the tenant crash. The test only failed later when it tried to query statement_statistics on the dead tenant.

This aligns exactly with @stevendanna's comment: "it looks like one of the tenants shut itself down because its liveness lease was lost, which implies that it did get starved out."

Root cause: The cpu-time-tokens variant uses concurrency=3500, which generates enormous load on both the SQL pod and the KV node. With 4 tenants × 3500 connections, the KV node is overwhelmed (300%+ CPU on 4 vCPUs). The admission controller's CPU target of 80% is met on average, but this high concurrency creates spikes where the KV node becomes unresponsive long enough for the sqlliveness heartbeat to fail.

Recommendations:

• Consider protecting sqlliveness heartbeats from admission control throttling or giving them higher priority to prevent starvation.
• Alternatively, increase the sqlliveness TTL for this test or reduce the concurrency to reduce the risk of heartbeat failure under extreme load.
• The test should either monitor tenant liveness during the workload phase or handle the case where a tenant dies (e.g., retry the connection, or fail with a more descriptive message).

Related Issues and PRs

• #171248 — This issue (first occurrence of this test failing)
• #150542 — multitenant-fairness/write-heavy/even failed with a similar pattern: pq: internal error while retrieving user account memberships: operation "get-user-session" timed out after 10s — also caused by tenant starvation
• #142517 — multitenant-fairness/read-heavy/even timed out (3h) — possibly related starvation
• #109545 — multitenant-fairness roachtests output invalid histograms (open)
• PR 479577bc5b9 — roachtest: add CPU time token admission control roachtests (May 1, 2026) — the commit that added this test variant

Timeline

Time	Event
09:56:22	Test starts, cockroach started on n1
09:56:41–09:58:47	Virtual clusters started on n2–n5
09:58:48	Data loading begins (concurrency=25 per tenant)
10:14:46	Data loading complete, 2-minute sleep begins
10:16:46	Main workloads start (concurrency=3500 per tenant)
10:25:07	Node 2 tenant: RSS at 6.0 GiB, 23k goroutines, 33% CPU
10:27:07	Node 2 tenant: RSS spikes to 7.2 GiB, CPU 140%
10:27:11	Node 2: slow RPCs (15–18s wait)
10:27:12	Node 2: sqlliveness heartbeat exits — "session record deleted"
10:27:12	Node 2: spontaneous shutdown initiated
10:27:14	Node 2: shutdown complete
10:36:54	All workloads complete (workload on n2 tolerated errors)
10:36:55	CPU utilization check passes (82.45%)
10:36:56	Test fails trying to query statement_statistics on dead n2

Detailed evidence and investigation notes

Log Excerpts

Node 2 sqlliveness shutdown sequence:

W260530 10:27:12.012707 333 sql/sqlliveness/slinstance/slinstance.go:337  exiting heartbeat loop
W260530 10:27:12.012744 333 sql/sqlliveness/slinstance/slinstance.go:324  exiting heartbeat loop with error: session record deleted
E260530 10:27:12.060849 933 jobs/job_scheduler.go:430  error executing schedules: find-scheduled-jobs: session record deleted
I260530 10:27:12.062753 939 cli/start.go:893  server requesting spontaneous shutdown: sql liveness session deleted
I260530 10:27:12.146036 1 cli/start.go:1052  initiating hard shutdown of server
W260530 10:27:14.583566 372273 server/server_sql.go:1860  server shutdown without a prior graceful drain
I260530 10:27:14.586422 1 cli/start.go:1123  server drained and shutdown completed

Node 2 runtime stats showing resource pressure (10:27:07):

runtime stats: 7.2 GiB RSS, 23192 goroutines (stacks: 558 MiB),
1.8 GiB/7.4 GiB Go alloc/total, 140.2/22.2 %(u/s)time

KV node 1 runtime stats (10:25:08):

runtime stats: 6.9 GiB RSS, 22033 goroutines (stacks: 963 MiB),
1.5 GiB/5.1 GiB Go alloc/total, 308.9/12.5 %(u/s)time

Node 2 slow RPCs just before shutdown:

W260530 10:27:11.286820 ... slow replica RPC: have been waiting 17.42s (0 attempts)
W260530 10:27:11.287397 ... slow replica RPC: have been waiting 16.88s (0 attempts)

Code References

The failure path through the code:

1. heartbeatLoopInner (slinstance.go:371-381): extendSession returns found=false because the session expired and was cleaned up. clearSession returns false (the event handler opts for shutdown), so the function returns errors.New("session record deleted").

2. heartbeatLoop (slinstance.go:320-332): Detects this is not a graceful drain, logs the warning, and propagates the error.

3. The server's spontaneous shutdown path in start.go:893 triggers a hard shutdown.

4. Later, runMultiTenantFairness at admission_control_multitenant_fairness.go:358-365 calls c.Conn(ctx, t.L(), node[0], ...) which dials port 29000 on the dead tenant, producing "connection refused".

Things Ruled Out

• OOM kill: No OOM kill in dmesg.txt for node 2. While memory was high (7.2 GiB RSS on a 16 GiB machine), it was not OOM-killed.
• Infrastructure issue: The other 3 tenants (n3, n4, n5) completed their workloads successfully. Only n2 crashed.
• Test logic bug: The test code correctly uses --tolerate-errors for the cpu-time-tokens variant workload, and the CPU utilization verification passed (82.45%). The issue is that the test does not handle a tenant dying during the workload.
• KV node crash: The KV node (n1) remained healthy throughout. Its CPU was saturated (300%+) but it didn't crash.

Other Failure Occurrences

This is the first occurrence of the cpu-time-tokens variant (added May 1, 2026 in commit 479577bc5b9). Prior related failures in non-cpu-time-tokens variants of the multitenant-fairness test show similar patterns of tenant starvation:

• roachtest: admission-control/multitenant-fairness/write-heavy/even failed #150542 (write-heavy/even): SQL liveness session timeout
• roachtest: admission-control/multitenant-fairness/read-heavy/even failed #142517 (read-heavy/even): Test timeout at 3h
• These failures indicate that tenant starvation under heavy admission control workloads is a recurring theme, and the cpu-time-tokens variant with its 14x higher concurrency exacerbates it.

Tooling Feedback

No tooling limitations encountered during this investigation.

---

Workflow run

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

[wenyihu6]

Given that this feature was recently introduced and no failures over the past two weeks (weekly test tho iirc), I'm removing the release blocker. I will continue investigating it as part of the RM project.