roachtest: perturbation/full/intents failed

[cockroach-teamcity]

roachtest.perturbation/full/intents failed with artifacts on release-25.1 @ 8d14dc1a0e70e635f317868d2d29992357401ce5:

(assertions.go:363).Fail: 
	Error Trace:	pkg/cmd/roachtest/tests/perturbation/framework.go:676
	            				pkg/cmd/roachtest/test_runner.go:1318
	            				src/runtime/asm_amd64.s:1695
	Error:      	Should be true
	Test:       	perturbation/full/intents
	Messages:   	FAILURE: follower-read  : Increase 635103.8854 > 40.0000 BASE: 5.668364ms SCORE: 1h0m0s
	            	
	            	FAILURE: read           : Increase 647222.6597 > 40.0000 BASE: 5.562228ms SCORE: 1h0m0s
	            	
	            	FAILURE: write          : Increase 428026.1029 > 40.0000 BASE: 8.410702ms SCORE: 1h0m0s
(require.go:1950).True: FailNow called
test artifacts and logs in: /artifacts/perturbation/full/intents/run_1

Parameters:

• acMode=defaultOption
• arch=amd64
• blockSize=4096
• cloud=gce
• coverageBuild=false
• cpu=16
• diskBandwidthLimit=0
• disks=2
• encrypted=false
• fillDuration=10m0s
• fs=ext4
• leaseType=epoch
• localSSD=true
• mem=standard
• numNodes=12
• numWorkloadNodes=1
• perturbationDuration=10m0s
• ratioOfMax=0.5
• runtimeAssertionsBuild=false
• seed=0
• splits=10000
• ssd=2
• validationDuration=5m0s
• vcpu=16

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-50983

[stevendanna]

It seems like we didn't record any recovery stats:

2025/05/26 13:21:04 framework.go:666: Recovery stats
follower-read  : 2025-05-26 13:11:18 +0000 UTC: score: 1h0m0s, qps: 0, p50: 0s, p99: 0s, pMax: 0s
read           : 2025-05-26 13:11:16 +0000 UTC: score: 1h0m0s, qps: 0, p50: 0s, p99: 0s, pMax: 0s
write          : 2025-05-26 13:11:18 +0000 UTC: score: 1h0m0s, qps: 0, p50: 0s, p99: 0s, pMax: 0s

This smells like a testing error since it seems unlikely that we did 0qps through the recovery period.

[stevendanna]

The workload command itself seems to have normal output during the recovery period. For example:

{"time":"2025-05-26T13:14:46.314654054Z","errs":0,"avgt":21135.7,"avgl":21059.1,"p50l":2.2,"p95l":11.5,"p99l":19.9,"maxl":41.9,"type":"write"}
{"time":"2025-05-26T13:14:47.314354122Z","errs":0,"avgt":10537.2,"avgl":10527.0,"p50l":1.1,"p95l":1.6,"p99l":2.8,"maxl":24.1,"type":"follower-read"}
{"time":"2025-05-26T13:14:47.314354122Z","errs":0,"avgt":10489.1,"avgl":10528.0,"p50l":1.0,"p95l":1.4,"p99l":2.1,"maxl":18.9,"type":"read"}
{"time":"2025-05-26T13:14:47.314354122Z","errs":0,"avgt":21217.4,"avgl":21059.2,"p50l":2.0,"p95l":10.0,"p99l":17.8,"maxl":56.6,"type":"write"}
{"time":"2025-05-26T13:14:48.314938803Z","errs":0,"avgt":10580.8,"avgl":10527.0,"p50l":1.1,"p95l":1.8,"p99l":4.7,"maxl":35.7,"type":"follower-read"}
{"time":"2025-05-26T13:14:48.314938803Z","errs":0,"avgt":10534.8,"avgl":10528.0,"p50l":1.0,"p95l":1.5,"p99l":3.0,"maxl":16.8,"type":"read"}
{"time":"2025-05-26T13:14:48.314938803Z","errs":0,"avgt":21122.6,"avgl":21059.3,"p50l":2.5,"p95l":12.1,"p99l":19.9,"maxl":48.2,"type":"write"}
{"time":"2025-05-26T13:14:49.314416409Z","errs":0,"avgt":10656.6,"avgl":10527.1,"p50l":1.1,"p95l":1.6,"p99l":3.9,"maxl":35.7,"type":"follower-read"}
{"time":"2025-05-26T13:14:49.314416409Z","errs":0,"avgt":10501.5,"avgl":10527.9,"p50l":1.0,"p95l":1.4,"p99l":2.5,"maxl":24.1,"type":"read"}
{"time":"2025-05-26T13:14:49.314416409Z","errs":0,"avgt":21123.0,"avgl":21059.3,"p50l":2.2,"p95l":10.5,"p99l":18.9,"maxl":35.7,"type":"write"}
{"time":"2025-05-26T13:14:50.314845823Z","errs":0,"avgt":10506.5,"avgl":10527.1,"p50l":1.0,"p95l":1.6,"p99l":2.8,"maxl":17.8,"type":"follower-read"}
{"time":"2025-05-26T13:14:50.314845823Z","errs":0,"avgt":10580.5,"avgl":10528.0,"p50l":1.0,"p95l":1.4,"p99l":1.9,"maxl":17.8,"type":"read"}
{"time":"2025-05-26T13:14:50.314845823Z","errs":0,"avgt":21123.9,"avgl":21059.3,"p50l":2.0,"p95l":9.4,"p99l":18.9,"maxl":46.1,"type":"write"}
{"time":"2025-05-26T13:14:51.314960261Z","errs":0,"avgt":10641.8,"avgl":10527.1,"p50l":1.1,"p95l":1.6,"p99l":4.5,"maxl":15.2,"type":"follower-read"}
{"time":"2025-05-26T13:14:51.314960261Z","errs":0,"avgt":10517.8,"avgl":10528.0,"p50l":1.0,"p95l":1.5,"p99l":2.9,"maxl":17.8,"type":"read"}
{"time":"2025-05-26T13:14:51.314960261Z","errs":0,"avgt":21111.6,"avgl":21059.4,"p50l":2.4,"p95l":11.5,"p99l":21.0,"maxl":41.9,"type":"write"}
{"time":"2025-05-26T13:14:52.314692295Z","errs":0,"avgt":10589.8,"avgl":10527.2,"p50l":1.1,"p95l":1.6,"p99l":3.5,"maxl":23.1,"type":"follower-read"}
{"time":"2025-05-26T13:14:52.314692295Z","errs":0,"avgt":10669.9,"avgl":10528.1,"p50l":1.0,"p95l":1.4,"p99l":2.4,"maxl":18.9,"type":"read"}
{"time":"2025-05-26T13:14:52.314692295Z","errs":0,"avgt":21005.6,"avgl":21059.3,"p50l":2.2,"p95l":10.0,"p99l":17.8,"maxl":35.7,"type":"write"}
{"time":"2025-05-26T13:14:53.314411852Z","errs":0,"avgt":10625.0,"avgl":10527.2,"p50l":1.1,"p95l":1.6,"p99l":2.8,"maxl":24.1,"type":"follower-read"}
{"time":"2025-05-26T13:14:53.314411852Z","errs":0,"avgt":10642.0,"avgl":10528.1,"p50l":1.0,"p95l":1.4,"p99l":2.1,"maxl":12.6,"type":"read"}

[stevendanna]

But, it seems we did have two periods that dropped to zero, and the perturbation tests look for the very worst tick inside a time interval:

"time":"2025-05-26T13:11:16.314079846Z","errs":0,"avgt":0.0,"avgl":10549.0,"p50l":0.0,"p95l":0.0,"p99l":0.0,"maxl":0.0,"type":"follower-read"}
{"time":"2025-05-26T13:11:16.314079846Z","errs":0,"avgt":0.0,"avgl":10552.4,"p50l":0.0,"p95l":0.0,"p99l":0.0,"maxl":0.0,"type":"read"}
{"time":"2025-05-26T13:11:16.314079846Z","errs":0,"avgt":0.0,"avgl":21106.5,"p50l":0.0,"p95l":0.0,"p99l":0.0,"maxl":0.0,"type":"write"}
{"time":"2025-05-26T13:11:17.314488592Z","errs":0,"avgt":1278.5,"avgl":10543.1,"p50l":1.1,"p95l":2.6,"p99l":2080.4,"maxl":2147.5,"type":"follower-read"}
{"time":"2025-05-26T13:11:17.314488592Z","errs":0,"avgt":1267.5,"avgl":10546.4,"p50l":1.0,"p95l":3.0,"p99l":41.9,"maxl":2147.5,"type":"read"}
{"time":"2025-05-26T13:11:17.314488592Z","errs":0,"avgt":2465.0,"avgl":21094.5,"p50l":1.9,"p95l":2415.9,"p99l":2550.1,"maxl":2550.1,"type":"write"}
{"time":"2025-05-26T13:11:18.313878836Z","errs":0,"avgt":0.0,"avgl":10536.3,"p50l":0.0,"p95l":0.0,"p99l":0.0,"maxl":0.0,"type":"follower-read"}
{"time":"2025-05-26T13:11:18.313878836Z","errs":0,"avgt":0.0,"avgl":10539.7,"p50l":0.0,"p95l":0.0,"p99l":0.0,"maxl":0.0,"type":"read"}
{"time":"2025-05-26T13:11:18.313878836Z","errs":0,"avgt":0.0,"avgl":21081.0,"p50l":0.0,"p95l":0.0,"p99l":0.0,"maxl":0.0,"type":"write"}