roachtest: perturbation/metamorphic/backup failed

[cockroach-teamcity]

roachtest.perturbation/metamorphic/backup failed with artifacts on master @ 007029617564b747e4f199c990860ad73f299c3a:

(assertions.go:363).Fail: 
	Error Trace:	pkg/cmd/roachtest/tests/perturbation/framework.go:673
	            				pkg/cmd/roachtest/test_runner.go:1318
	            				src/runtime/asm_amd64.s:1695
	Error:      	Should be true
	Test:       	perturbation/metamorphic/backup
	Messages:   	FAILURE: follower-read  : Increase 5.2226 > 5.0000 BASE: 5.084987ms SCORE: 26.556933ms
	            	
	            	FAILURE: read           : Increase 5.5827 > 5.0000 BASE: 4.794291ms SCORE: 26.764958ms
(require.go:1950).True: FailNow called
test artifacts and logs in: /artifacts/perturbation/metamorphic/backup/run_1

Parameters:

• acMode=elasticOnlyBoth
• arch=amd64
• blockSize=1024
• cloud=gce
• coverageBuild=false
• cpu=16
• diskBandwidthLimit=0
• disks=1
• encrypted=false
• fillDuration=10m0s
• fs=ext4
• leaseType=epoch
• localSSD=true
• mem=low
• numNodes=12
• numWorkloadNodes=1
• perturbationDuration=10m0s
• ratioOfMax=0.5
• runtimeAssertionsBuild=false
• seed=-1281374512680486222
• splits=10000
• ssd=1
• 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-47790

[cockroach-teamcity]

roachtest.perturbation/metamorphic/backup failed with artifacts on master @ 22b262749c502d07ec7ccec5b76abd67c361ae4d:

(assertions.go:363).Fail: 
	Error Trace:	pkg/cmd/roachtest/tests/perturbation/framework.go:673
	            				pkg/cmd/roachtest/test_runner.go:1333
	            				src/runtime/asm_amd64.s:1695
	Error:      	Should be true
	Test:       	perturbation/metamorphic/backup
	Messages:   	FAILURE: follower-read  : Increase 6.5683 > 5.0000 BASE: 9.932716ms SCORE: 65.241379ms
	            	
	            	FAILURE: read           : Increase 7.0568 > 5.0000 BASE: 9.19911ms SCORE: 64.916638ms
	            	
	            	FAILURE: write          : Increase 6.4908 > 5.0000 BASE: 8.548603ms SCORE: 55.487274ms
(require.go:1950).True: FailNow called
test artifacts and logs in: /artifacts/perturbation/metamorphic/backup/run_1

Parameters:

• acMode=elasticOnlyBoth
• arch=amd64
• blockSize=1
• cloud=gce
• coverageBuild=false
• cpu=8
• diskBandwidthLimit=0
• disks=2
• encrypted=false
• fillDuration=10m0s
• fs=ext4
• leaseType=leader
• localSSD=true
• mem=high
• metamorphicBufferedSender=false
• numNodes=30
• numWorkloadNodes=2
• perturbationDuration=10m0s
• ratioOfMax=0.5
• runtimeAssertionsBuild=false
• seed=-4560564344843122036
• splits=10000
• ssd=2
• validationDuration=5m0s
• vcpu=8

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

This test on roachdash | Improve this report!

[tbg]

Looking at the failure just above.

p99s were too high during recovery interval. The backup (which is the perturbation here) finished at 7:14:12, lining up well with the beginning of the recovery interval. p99s go up right after.

This point in time also lines up with elastic bytes deducted and returned, which I find surprising. What's that about? The backup just finished, and it shouldn't cause this anyway.

Closedts fell behind on n21

7:15am

Notable events from the log at around 7:15:

cockroach-healthI250214 07:15:09.702270 304 2@kv/kvserver/replica_proposal.go:620 ⋮ [T1,Vsystem,n19,s37,r72/13:‹/Table/7{0-1}›,raft] 867  new range lease repl=(n19,s37):13 seq=9 start=1739517309.701119713,0 exp=1739517315.701053841,0 pro=1739517309.701053841,0 acq=Transf>

cockroachW250214 07:15:09.731283 15020 kv/kvserver/closedts/sidetransport/receiver.go:135 ⋮ [T1,n25,remote=28] 4225  closed timestamps side-transport connection dropped from node: 28 (grpc: ‹context canceled› [code 1/Canceled])

cockroachI250214 07:15:10.448945 405047 1@jobs/structured_log.go:49 ⋮ [T1,Vsystem,n24] 4233 ={"Timestamp":1739517310448941860,"EventType":"status_change","JobID":1046763583623168024,"JobType":"AUTO CREATE STATS","Description":"state changed to: succeeded","PreviousStatus>
cockroachI250214 07:15:10.485752 410468 1@jobs/structured_log.go:49 ⋮ [T1,Vsystem,n24] 4234 ={"Timestamp":1739517310485747839,"EventType":"status_change","JobID":1046763636164722712,"JobType":"AUTO CREATE STATS","Description":"state changed to: running","PreviousStatus":>
cockroachI250214 07:15:10.492255 410468 sql/distsql_plan_stats.go:208 ⋮ [T1,Vsystem,n24,job=AUTO CREATE STATS id=1046763636164722712,create-stats-distsql] 4235  using computed sample size of 10000 for histogram construction

So there clearly was something going on at 07:15 that the latencies picked up on (at least on the Grafana dashboards, presumably also in the kv workload logs). The RPC connection closure is strange and unexplained.

7:17am

The test prints the worst 1s interval's p99 etc here). We see it got worst at 7:17, with max spiking into the 783ms range. That's interesting because 7:17 is not on my radar at all from looking at the graphs, but the kv output proves it:

Details

{"time":"2025-02-14T07:17:15.490670471Z","errs":0,"avgt":9686.0,"avgl":9732.9,"p50l":0.9,"p95l":1.1,"p99l":1.5,"maxl":8.1,"type":"read"}
{"time":"2025-02-14T07:17:15.490670471Z","errs":0,"avgt":19404.0,"avgl":19455.1,"p50l":1.4,"p95l":1.9,"p99l":2.5,"maxl":13.1,"type":"write"}
{"time":"2025-02-14T07:17:16.451632249Z","errs":0,"avgt":7925.0,"avgl":9723.9,"p50l":0.9,"p95l":1.3,"p99l":5.2,"maxl":704.6,"type":"follower-read"}
{"time":"2025-02-14T07:17:16.451632249Z","errs":0,"avgt":7768.1,"avgl":9727.0,"p50l":0.9,"p95l":1.2,"p99l":234.9,"maxl":738.2,"type":"read"}
{"time":"2025-02-14T07:17:16.451632249Z","errs":0,"avgt":15750.1,"avgl":19456.0,"p50l":1.4,"p95l":2.0,"p99l":402.7,"maxl":738.2,"type":"write"}
{"time":"2025-02-14T07:17:16.49167562Z","errs":0,"avgt":8065.9,"avgl":9730.8,"p50l":0.9,"p95l":1.4,"p99l":285.2,"maxl":738.2,"type":"follower-read"}
{"time":"2025-02-14T07:17:16.49167562Z","errs":0,"avgt":8146.8,"avgl":9729.8,"p50l":0.9,"p95l":1.3,"p99l":285.2,"maxl":738.2,"type":"read"}
{"time":"2025-02-14T07:17:16.49167562Z","errs":0,"avgt":16296.6,"avgl":19448.8,"p50l":1.4,"p95l":2.2,"p99l":302.0,"maxl":671.1,"type":"write"}
{"time":"2025-02-14T07:17:17.451567756Z","errs":0,"avgt":9722.6,"avgl":9723.9,"p50l":0.9,"p95l":1.3,"p99l":16.3,"maxl":385.9,"type":"follower-read"}
{"time":"2025-02-14T07:17:17.451567756Z","errs":0,"avgt":9665.6,"avgl":9726.8,"p50l":0.9,"p95l":1.2,"p99l":14.7,"maxl":385.9,"type":"read"}
{"time":"2025-02-14T07:17:17.451567756Z","errs":0,"avgt":19798.3,"avgl":19456.7,"p50l":1.4,"p95l":2.0,"p99l":15.7,"maxl":402.7,"type":"write"}
{"time":"2025-02-14T07:17:17.490802187Z","errs":0,"avgt":9793.6,"avgl":9730.9,"p50l":0.9,"p95l":1.3,"p99l":2.2,"maxl":27.3,"type":"follower-read"}
{"time":"2025-02-14T07:17:17.490802187Z","errs":0,"avgt":9667.4,"avgl":9729.6,"p50l":0.9,"p95l":1.2,"p99l":2.6,"maxl":35.7,"type":"read"}

At 7:17, we see a merge, with associated snapshot activity etc, so that likely explains the 1-2 seconds of elevated latencies.

Details

cockroach-healthI250214 07:17:36.814216 359 2@gossip/gossip.go:559 ⋮ [T1,Vsystem,n2] 961 +  18: ‹10.142.2.76:26257› (21m5s)
cockroachI250214 07:17:37.266631 509341 1@jobs/structured_log.go:49 ⋮ [T1,Vsystem,n6] 3563 ={"Timestamp":1739517457266627267,"EventType":"status_change","JobID":1046764117133950982,"JobType":"AUTO CREATE STATS","Description":"state changed to: running","PreviousStatus":">
cockroachI250214 07:17:37.274285 509341 sql/distsql_plan_stats.go:208 ⋮ [T1,Vsystem,n6,job=AUTO CREATE STATS id=1046764117133950982,create-stats-distsql] 3564  using computed sample size of 10000 for histogram construction
cockroachI250214 07:17:37.437072 509341 1@jobs/structured_log.go:49 ⋮ [T1,Vsystem,n6] 3565 ={"Timestamp":1739517457437069521,"EventType":"status_change","JobID":1046764117133950982,"JobType":"AUTO CREATE STATS","Description":"state changed to: succeeded","PreviousStatus">
cockroachI250214 07:17:37.503349 336 kv/kvserver/storeliveness/support_manager.go:148 ⋮ [T1,-] 3429  store {NodeID:21 StoreID:41} is starting to heartbeat store {NodeID:28 StoreID:55} (after being idle)
cockroachI250214 07:17:37.510348 459178 kv/kvserver/replica_raftstorage.go:527 ⋮ [T1,Vsystem,n28,s55,r53/17:‹/Table/5{1-2}›] 3980  applied snapshot a4badcf3 from (n21,s41):16 at applied index 165 ‹as write ›(total=2ms data=4.9 KiB excise=true ingestion=6@0ms)
cockroachI250214 07:17:37.529703 339 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n22,s43,r53/15:‹/Table/5{1-2}›,raft] 3473  removing replica r53/15
cockroachW250214 07:17:37.538534 349 kv/kvserver/replica_store_liveness.go:66 ⋮ [T1,Vsystem,n16,s31,r53/18:{-}] 3752  store not found for replica 16 in SupportFor
cockroachI250214 07:17:37.544101 452036 kv/kvserver/replica_raftstorage.go:527 ⋮ [T1,Vsystem,n16,s31,r53/18:‹/Table/5{1-2}›] 3753  applied snapshot f7de2cec from (n21,s41):16 at applied index 174 ‹as write ›(total=1ms data=5.7 KiB excise=true ingestion=6@0ms)
cockroachI250214 07:17:37.563671 524 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n6,s12,r53/7:‹/Table/5{1-2}›,raft] 3566  removing replica r53/7
cockroachW250214 07:17:37.572141 300 kv/kvserver/replica_store_liveness.go:66 ⋮ [T1,Vsystem,n7,s13,r53/19:{-}] 3420  store not found for replica 16 in SupportFor
cockroachI250214 07:17:37.577831 468278 kv/kvserver/replica_raftstorage.go:527 ⋮ [T1,Vsystem,n7,s13,r53/19:‹/Table/5{1-2}›] 3421  applied snapshot 2ac0c1fd from (n21,s41):16 at applied index 183 ‹as write ›(total=2ms data=6.5 KiB excise=true ingestion=6@1ms)
cockroachI250214 07:17:37.597238 301 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n8,s15,r53/8:‹/Table/5{1-2}›,raft] 3793  removing replica r53/8
cockroachW250214 07:17:37.605743 469 kv/kvserver/replica_store_liveness.go:66 ⋮ [T1,Vsystem,n3,s6,r53/20:{-}] 4159  store not found for replica 16 in SupportFor
cockroachI250214 07:17:37.611756 510260 kv/kvserver/replica_raftstorage.go:527 ⋮ [T1,Vsystem,n3,s6,r53/20:‹/Table/5{1-2}›] 4160  applied snapshot fd8ffb6a from (n21,s41):16 at applied index 192 ‹as write ›(total=2ms data=7.4 KiB excise=true ingestion=6@1ms)
cockroach-healthI250214 07:17:37.616382 471 2@kv/kvserver/replica_proposal.go:620 ⋮ [T1,Vsystem,n3,s6,r53/20:‹/Table/5{1-2}›,raft] 952  new range lease repl=(n3,s6):20VOTER_INCOMING seq=8 start=1739517457.615424938,0 exp=1739517463.615344912,0 pro=1739517457.615344912,0 >
cockroachI250214 07:17:37.617124 470 kv/kvserver/storeliveness/support_manager.go:148 ⋮ [T1,-] 4161  store {NodeID:3 StoreID:6} is starting to heartbeat store {NodeID:7 StoreID:13} (after being idle)
cockroachI250214 07:17:37.632314 334 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n21,s41,r53/16:‹/Table/5{1-2}›,raft] 3430  removing replica r53/16
cockroachW250214 07:17:37.642091 307 kv/kvserver/replica_store_liveness.go:66 ⋮ [T1,Vsystem,n23,s45,r53/21:{-}] 4381  store not found for replica 20 in SupportFor
cockroachI250214 07:17:37.648714 462163 kv/kvserver/replica_raftstorage.go:527 ⋮ [T1,Vsystem,n23,s45,r53/21:‹/Table/5{1-2}›] 4382  applied snapshot 6abb0a66 from (n3,s6):20 at applied index 204 ‹as write ›(total=2ms data=8.2 KiB excise=true ingestion=6@1ms)
cockroachI250214 07:17:37.669299 299 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n13,s25,r53/10:‹/Table/5{1-2}›,raft] 4444  removing replica r53/10
cockroachI250214 07:17:37.671375 459252 kv/kvserver/replica_command.go:842 ⋮ [T1,Vsystem,n28,merge,s55,r52/17:‹/Table/5{0-1}›] 3981  initiating a merge of r53:‹/Table/5{1-2}› [(n7,s13):19, (n16,s31):18, (n3,s6):20, (n23,s45):21, (n28,s55):17, next=22, gen=72] into this r>
cockroachI250214 07:17:37.675990 510291 kv/kvserver/replica_command.go:2465 ⋮ [T1,Vsystem,n3,replicate,s6,r53/20:‹/Table/5{1-2}›] 4162  we were trying to exit a joint config but found that we are no longer in one; skipping
cockroachI250214 07:17:37.678790 271 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n28,s55,r52/17:‹/Table/5{0-1}›,raft] 3982  removing replica r53/17
cockroachI250214 07:17:37.678973 286 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n7,s13,r52/7:‹/Table/5{0-1}›,raft] 3422  removing replica r53/19
cockroachI250214 07:17:37.679011 462 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n3,s6,r52/19:‹/Table/5{0-1}›,raft] 4163  removing replica r53/20
cockroachI250214 07:17:37.679054 326 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n16,s31,r52/12:‹/Table/5{0-1}›,raft] 3754  removing replica r53/18
cockroachI250214 07:17:37.679090 288 kv/kvserver/store_remove_replica.go:152 ⋮ [T1,Vsystem,n23,s45,r52/15:‹/Table/5{0-1}›,raft] 4383  removing replica r53/21

I think we just can't have merges with these tight latency bounds.

General notes

Generally the output is somewhat obfuscated, mostly due to the way it's presented.

For example here:

2025/02/14 07:19:14 framework.go:748: FAILURE: read           : Increase 7.0568 > 5.0000 BASE: 9.19911ms SCORE: 64.916638ms

this really means: "some blended mix of p99 and p95 latencies"¹ was 9.199 before, now it's 64.916, which is a 7.0568x increase, and we were going to tolerate a 5x increase at most.

I'm going to remove the release blocker label, since it's a perturbation test and nothing has obviously gone wrong here.

There's a scoreCalculator type² which isn't used.

Footnotes

1. https://github.com/cockroachdb/cockroach/blob/e41ca5252427ac120a9e7557749bd7f1848fda34/pkg/cmd/roachtest/tests/perturbation/framework.go#L697-L698 ↩

2. https://github.com/cockroachdb/cockroach/blob/e41ca5252427ac120a9e7557749bd7f1848fda34/pkg/cmd/roachtest/tests/perturbation/framework.go#L704 ↩