sql/sem/builtins: TestGetSSTableMetricsMultiNode failed

[cockroach-teamcity]

sql/sem/builtins.TestGetSSTableMetricsMultiNode failed on release-24.1 @ 83796af55775f4641055129caa7dba562d0ed8c9:

=== RUN   TestGetSSTableMetricsMultiNode
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestGetSSTableMetricsMultiNode3156966246
    test_log_scope.go:81: use -show-logs to present logs inline
    test_server_shim.go:144: cluster virtualization disabled in global scope due to issue: #76378 (expected label: C-bug)
    generator_builtins_test.go:79: error executing query="INSERT INTO t SELECT i, i*10 FROM generate_series(1, 10000) AS g(i)" args=[]: pq: result is ambiguous: error=r69/1:(n1,s1) is unavailable (circuit breaker tripped): context canceled [propagate] (last error: WriteTooOldError: write for key /Table/104/1/5701/0 at timestamp 1713347490.525215347,0 too old; must write at or above 1713347572.700440902,2: "sql txn" meta={id=74fcb5a0 key=/Table/104/1/1/0 iso=Serializable pri=0.01001894 epo=0 ts=1713347572.700440902,2 min=1713347490.525215347,0 seq=10000} lock=true stat=PENDING rts=1713347490.525215347,0 wto=false gul=1713347491.025215347,0)
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestGetSSTableMetricsMultiNode3156966246
--- FAIL: TestGetSSTableMetricsMultiNode (255.78s)

Parameters:

• attempt=1
• race=true
• run=3
• shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/sql-foundations

This test on roachdash | Improve this report!

Jira issue: CRDB-37943

[rafiss]

Moving to Storage team as they own this test.

[sumeerbhola]

The failure happens during the data insertion by SQL before querying the metric:

 generator_builtins_test.go:79: error executing query="INSERT INTO t SELECT i, i*10 FROM generate_series(1, 10000) AS g(i)" args=[]: pq: result is ambiguous: error=r69/1:(n1,s1) is unavailable (circuit breaker tripped): context canceled [propagate] (last error: WriteTooOldError: write for key /Table/104/1/5701/0 at timestamp 1713347490.525215347,0 too old; must write at or above 1713347572.700440902,2: "sql txn" meta={id=74fcb5a0 key=/Table/104/1/1/0 iso=Serializable pri=0.01001894 epo=0 ts=1713347572.700440902,2 min=1713347490.525215347,0 seq=10000} lock=true stat=PENDING rts=1713347490.525215347,0 wto=false gul=1713347491.025215347,0)

I don't know why that single statement transaction is not retried. Looking at the n1 logs there are many slow statements:

E240417 09:53:17.067554 61809 kv/kvclient/kvcoord/dist_sender_circuit_breaker.go:1016 ⋮ [T1,Vsystem,n3] 1171  r69/1:(n1,s1) circuit breaker tripped: probe timed out: context deadline exceeded (stalled for 8.545s, erroring for 0s)
W240417 09:53:17.623841 57108 kv/kvserver/spanlatch/manager.go:654 ⋮ [T1,Vsystem,n1,s1,r69/1:‹/{Table/104-Max}›] 1172  ConditionalPut [/Table/104/1/‹5701›/‹0›], ConditionalPut [/Table/104/1/‹5702›/‹0›], ConditionalPut [/Table/104/1/‹5703›/‹0›], ConditionalPut [/Table/104/1/‹5704›/‹0›], ConditionalPut [/Table/104/1/‹5705›/‹0›], ConditionalPut [/Table/104/1/‹5706›/‹0›], ConditionalPut [/Table/104/1/‹5707›/‹0›], ConditionalPut [/Table/104/1/‹5708›/‹0›], ConditionalPut [/Table/104/1/‹5709›/‹0›], ConditionalPut [/Table/104/1/‹5710›/‹0›], ConditionalPut [/Table/104/1/‹5711›/‹0›], ConditionalPut [/Table/104/1/‹5712›/‹0›], ConditionalPut [/Table/104/1/‹5713›/‹0›], ConditionalPut [/Table/104/1/‹5714›/‹0›], ConditionalPut [/Table/104/1/‹5715›/‹0›], ConditionalPut [/Table/104/1/‹5716›/‹0›], ConditionalPut [/Table/104/1/‹5717›/‹0›], ConditionalPut [/Table/104/1/‹5718›/‹0›], ConditionalPut [/Table/104/1/‹5719›/‹0›], ConditionalPut [/Table/104/1/‹5720›/‹0›],... 4276 skipped ..., ConditionalPut [/Table/104/1/‹9997›/‹0›], ConditionalPut [/Table/104/1/‹9998›/‹0›], ConditionalPut [/Table/104/1/‹9999›/‹0›], ConditionalPut [/Table/104/1/‹10000›/‹0›], EndTxn(commit) [/Table/104/1/‹1›/‹0›], [txn: 74fcb5a0] has held latch for 21764004291 ns. Some possible causes are slow disk reads, slow raft replication, and expensive request processing.
W240417 09:53:17.736295 57006 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n3] 1173  slow replica RPC: have been waiting 37.98s (0 attempts) for RPC ConditionalPut [/Table/104/1/‹5701›/‹0›], ConditionalPut [/Table/104/1/‹5702›/‹0›], ConditionalPut [/Table/104/1/‹5703›/‹0›], ConditionalPut [/Table/104/1/‹5704›/‹0›], ConditionalPut [/Table/104/1/‹5705›/‹0›], ConditionalPut [/Table/104/1/‹5706›/‹0›], ConditionalPut [/Table/104/1/‹5707›/‹0›], ConditionalPut [/Table/104/1/‹5708›/‹0›], ConditionalPut [/Table/104/1/‹5709›/‹0›], ConditionalPut [/Table/104/1/‹5710›/‹0›], ConditionalPut [/Table/104/1/‹5711›/‹0›], ConditionalPut [/Table/104/1/‹5712›/‹0›], ConditionalPut [/Table/104/1/‹5713›/‹0›], ConditionalPut [/Table/104/1/‹5714›/‹0›], ConditionalPut [/Table/104/1/‹5715›/‹0›], ConditionalPut [/Table/104/1/‹5716›/‹0›], ConditionalPut [/Table/104/1/‹5717›/‹0›], ConditionalPut [/Table/104/1/‹5718›/‹0›], ConditionalPut [/Table/104/1/‹5719›/‹0›], ConditionalPut [/Table/104/1/‹5720›/‹0›],... 4276 skipped ..., ConditionalPut [/Table/104/1/‹9997›/‹0›], ConditionalPut [/Table/104/1/‹9998›/‹0›], ConditionalPut [/Table/104/1/‹9999›/‹0›], ConditionalPut [/Table/104/1/‹10000›/‹0›], EndTxn(parallel commit) [/Table/104/1/‹1›/‹0›], [txn: 74fcb5a0] to replica (n1,s1):1; resp: ‹(err: WriteTooOldError: write for key /Table/104/1/5701/0 at timestamp 1713347490.525215347,0 too old; must write at or above 1713347572.700440902,2: "sql txn" meta={id=74fcb5a0 key=/Table/104/1/1/0 iso=Serializable pri=0.01001894 epo=0 ts=1713347572.700440902,2 min=1713347490.525215347,0 seq=10000} lock=true stat=PENDING rts=1713347490.525215347,0 wto=false gul=1713347491.025215347,0)›
W240417 09:53:17.816347 47291 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n1,client=127.0.0.1:45838,hostssl,user=root] 1174  slow replica RPC: have been waiting 38.50s (1 attempts) for RPC ConditionalPut [/Table/104/1/‹5701›/‹0›], ConditionalPut [/Table/104/1/‹5702›/‹0›], ConditionalPut [/Table/104/1/‹5703›/‹0›], ConditionalPut [/Table/104/1/‹5704›/‹0›], ConditionalPut [/Table/104/1/‹5705›/‹0›], ConditionalPut [/Table/104/1/‹5706›/‹0›], ConditionalPut [/Table/104/1/‹5707›/‹0›], ConditionalPut [/Table/104/1/‹5708›/‹0›], ConditionalPut [/Table/104/1/‹5709›/‹0›], ConditionalPut [/Table/104/1/‹5710›/‹0›], ConditionalPut [/Table/104/1/‹5711›/‹0›], ConditionalPut [/Table/104/1/‹5712›/‹0›], ConditionalPut [/Table/104/1/‹5713›/‹0›], ConditionalPut [/Table/104/1/‹5714›/‹0›], ConditionalPut [/Table/104/1/‹5715›/‹0›], ConditionalPut [/Table/104/1/‹5716›/‹0›], ConditionalPut [/Table/104/1/‹5717›/‹0›], ConditionalPut [/Table/104/1/‹5718›/‹0›], ConditionalPut [/Table/104/1/‹5719›/‹0›], ConditionalPut [/Table/104/1/‹5720›/‹0›],... 4276 skipped ..., ConditionalPut [/Table/104/1/‹9997›/‹0›], ConditionalPut [/Table/104/1/‹9998›/‹0›], ConditionalPut [/Table/104/1/‹9999›/‹0›], ConditionalPut [/Table/104/1/‹10000›/‹0›], EndTxn(parallel commit) [/Table/104/1/‹1›/‹0›], [txn: 74fcb5a0], [protect-ambiguous-replay] to replica (n3,s3):3; resp: ‹(err: WriteTooOldError: write for key /Table/104/1/5701/0 at timestamp 1713347490.525215347,0 too old; must write at or above 1713347572.700440902,2: "sql txn" meta={id=74fcb5a0 key=/Table/104/1/1/0 iso=Serializable pri=0.01001894 epo=0 ts=1713347572.700440902,2 min=1713347490.525215347,0 seq=10000} lock=true stat=PENDING rts=1713347490.525215347,0 wto=false gul=1713347491.025215347,0)›
W240417 09:53:17.820221 47291 kv/kvclient/kvcoord/dist_sender.go:2086 ⋮ [T1,Vsystem,n1,client=127.0.0.1:45838,hostssl,user=root] 1175  slow range RPC: have been waiting 84.08s (1 attempts) for RPC ConditionalPut [/Table/104/1/‹5701›/‹0›], ConditionalPut [/Table/104/1/‹5702›/‹0›], ConditionalPut [/Table/104/1/‹5703›/‹0›], ConditionalPut [/Table/104/1/‹5704›/‹0›], ConditionalPut [/Table/104/1/‹5705›/‹0›], ConditionalPut [/Table/104/1/‹5706›/‹0›], ConditionalPut [/Table/104/1/‹5707›/‹0›], ConditionalPut [/Table/104/1/‹5708›/‹0›], ConditionalPut [/Table/104/1/‹5709›/‹0›], ConditionalPut [/Table/104/1/‹5710›/‹0›], ConditionalPut [/Table/104/1/‹5711›/‹0›], ConditionalPut [/Table/104/1/‹5712›/‹0›], ConditionalPut [/Table/104/1/‹5713›/‹0›], ConditionalPut [/Table/104/1/‹5714›/‹0›], ConditionalPut [/Table/104/1/‹5715›/‹0›], ConditionalPut [/Table/104/1/‹5716›/‹0›], ConditionalPut [/Table/104/1/‹5717›/‹0›], ConditionalPut [/Table/104/1/‹5718›/‹0›], ConditionalPut [/Table/104/1/‹5719›/‹0›], ConditionalPut [/Table/104/1/‹5720›/‹0›],... 4276 skipped ..., ConditionalPut [/Table/104/1/‹9997›/‹0›], ConditionalPut [/Table/104/1/‹9998›/‹0›], ConditionalPut [/Table/104/1/‹9999›/‹0›], ConditionalPut [/Table/104/1/‹10000›/‹0›], EndTxn(parallel commit) [/Table/104/1/‹1›/‹0›], [txn: 74fcb5a0], [can-forward-ts] to r69:‹/{Table/104-Max}› [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=5]; resp: result is ambiguous: error=r69/1:(n1,s1) is unavailable (circuit breaker tripped): context canceled [propagate] (last error: WriteTooOldError: write for key /Table/104/1/‹5701›/‹0› at timestamp 1713347490.525215347,0 too old; must write at or above 1713347572.700440902,2: "sql txn" meta={id=74fcb5a0 key=/Table/104/1/‹1›/‹0› iso=Serializable pri=0.01001894 epo=0 ts=1713347572.700440902,2 min=1713347490.525215347,0 seq=10000} lock=true stat=PENDING rts=1713347490.525215347,0 wto=false gul=1713347491.025215347,0)
W240417 09:53:17.821614 47291 kv/kvclient/kvcoord/dist_sender.go:2096 ⋮ [T1,Vsystem,n1,client=127.0.0.1:45838,hostssl,user=root] 1176  slow RPC response: slow RPC finished after 84.08s (1 attempts)
I240417 09:53:17.958594 61809 kv/kvclient/kvcoord/dist_sender_circuit_breaker.go:1045 ⋮ [T1,Vsystem,n3] 1177  r69/1:(n1,s1) circuit breaker reset
W240417 09:53:18.480198 23037 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n3,rnode=1,raddr=‹127.0.0.1:33217›,class=system,rpc] 1178  latency jump (prev avg 224.30ms, current 355.53ms)
W240417 09:53:18.578343 23357 2@rpc/clock_offset.go:291 ⋮ [T1,Vsystem,n1,rnode=3,raddr=‹127.0.0.1:46097›,class=default,rpc] 1179  latency jump (prev avg 221.30ms, current 396.19ms)

The test is very fast on my macbook (~2s), so shouldn't be a cpu overload issue. The n1 logs last 4min, so something was slow. Assigning to KV in case there are any obvious insights. Feel free to close if it may be something like a slow disk (infra flake).

[arulajmani]

This looks like overload, so I'll close this out as an infra flake (may be related to the test running on engflow). We see lots of slow range RPCs, like mentioned above, slow handle raft ready handling, and slow liveness heartbeats.

[blathers-crl]

cc @cockroachdb/test-eng