ccl/multiregionccl: TestMultiRegionDataDriven failed #108759
Description
ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1.9-rc @ 4eaa6718d63576fe7d63293c030df70ccd9ed0d2:
0.847ms 0.016ms event:sql/flowinfra/flow.go:462 [n1,client=127.0.0.1:56160,hostssl,user=root] starting (0 processors, 0 startables) asynchronously
0.859ms 0.012ms event:sql/colflow/vectorized_flow.go:323 [n1,client=127.0.0.1:56160,hostssl,user=root] running the batch flow coordinator in the flow's goroutine
0.860ms 0.001ms === operation:batch flow coordinator _verbose:1 node:1 client:127.0.0.1:56160 hostssl: user:root cockroach.flowid:6ee68e59-4006-4414-a736-58526498c404 cockroach.processorid:0
0.860ms 0.000ms [colbatchscan: {count: 1, duration 964µs, unfinished}]
0.860ms 0.000ms [txn coordinator send: {count: 1, duration 750µs}]
0.860ms 0.000ms [dist sender send: {count: 1, duration 688µs}]
0.860ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 453µs}]
0.866ms 0.006ms === operation:colbatchscan _unfinished:1 _verbose:1 node:1 client:127.0.0.1:56160 hostssl: user:root cockroach.flowid:6ee68e59-4006-4414-a736-58526498c404 cockroach.processorid:0
0.866ms 0.000ms [txn coordinator send: {count: 1, duration 750µs}]
0.866ms 0.000ms [dist sender send: {count: 1, duration 688µs}]
0.866ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 453µs}]
0.907ms 0.041ms event:sql/row/kv_batch_fetcher.go:475 [n1,client=127.0.0.1:56160,hostssl,user=root] Scan /Table/108/1/1/0
0.911ms 0.004ms === operation:txn coordinator send _verbose:1 node:1 client:127.0.0.1:56160 hostssl: user:root txnID:d9429de6-b77e-461a-8954-815a8da3cb46
0.911ms 0.000ms [dist sender send: {count: 1, duration 688µs}]
0.911ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 453µs}]
0.922ms 0.011ms === operation:dist sender send _verbose:1 node:1 client:127.0.0.1:56160 hostssl: user:root txn:d9429de6
0.922ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 453µs}]
0.958ms 0.035ms event:kv/kvclient/kvcoord/range_iter.go:188 [n1,client=127.0.0.1:56160,hostssl,user=root,txn=d9429de6] querying next range at /Table/108/1/1/0
1.027ms 0.069ms event:kv/kvclient/kvcoord/range_iter.go:225 [n1,client=127.0.0.1:56160,hostssl,user=root,txn=d9429de6] key: /Table/108/1/1/0, desc: r64:/{Table/108-Max} [(n1,s1):1, (n3,s3):9, (n2,s2):5, (n4,s4):6NON_VOTER, (n5,s5):8NON_VOTER, next=10, gen=23]
1.051ms 0.024ms event:kv/kvclient/kvcoord/dist_sender.go:2088 [n1,client=127.0.0.1:56160,hostssl,user=root,txn=d9429de6] routing to nearest replica; leaseholder not required
1.092ms 0.041ms event:kv/kvclient/kvcoord/dist_sender.go:2146 [n1,client=127.0.0.1:56160,hostssl,user=root,txn=d9429de6] r64: sending batch 1 Get to (n1,s1):1
1.110ms 0.018ms event:rpc/nodedialer/nodedialer.go:157 [n1,client=127.0.0.1:56160,hostssl,user=root,txn=d9429de6] sending request to local client
1.121ms 0.011ms === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: d9429de6], [can-forward-ts]
1.134ms 0.013ms event:server/node.go:1187 [n1] node received request: 1 Get
1.179ms 0.045ms event:kv/kvserver/store_send.go:167 [n1,s1] executing Get [/Table/108/1/1/0,/Min), [txn: d9429de6], [can-forward-ts]
1.198ms 0.019ms event:kv/kvserver/replica_send.go:179 [n1,s1,r64/1:/{Table/108-Max}] read-only path
1.217ms 0.019ms event:kv/kvserver/concurrency/concurrency_manager.go:208 [n1,s1,r64/1:/{Table/108-Max}] sequencing request
1.234ms 0.017ms event:kv/kvserver/concurrency/concurrency_manager.go:289 [n1,s1,r64/1:/{Table/108-Max}] acquiring latches
1.250ms 0.016ms event:kv/kvserver/concurrency/concurrency_manager.go:333 [n1,s1,r64/1:/{Table/108-Max}] scanning lock table for conflicting locks
1.275ms 0.025ms event:kv/kvserver/replica_follower_read.go:127 [n1,s1,r64/1:/{Table/108-Max}] serving via follower read; query timestamp below closed timestamp by 246.255412ms
1.317ms 0.042ms event:kv/kvserver/replica_read.go:296 [n1,s1,r64/1:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: d9429de6], [can-forward-ts]); scanning lock table first to detect conflicts
1.354ms 0.037ms event:kv/kvserver/replica_read.go:113 [n1,s1,r64/1:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
1.366ms 0.012ms event:kv/kvserver/replica_read.go:408 [n1,s1,r64/1:/{Table/108-Max}] executing read-only batch
1.486ms 0.120ms event:kv/kvserver/replica_evaluate.go:550 [n1,s1,r64/1:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=d9429de6 key=/Min pri=0.03477186 epo=0 ts=1692085562.233463366,0 min=1692085562.233463366,0 seq=0} lock=false stat=PENDING rts=1692085562.233463366,0 wto=false gul=1692085562.733463366,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1692085549524253391 > > , err=<nil>
1.534ms 0.048ms event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 6.4 KiB, cached 6.4 KiB); points: (count 1 , key-bytes 14 B, value-bytes 7 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
1.551ms 0.017ms event:kv/kvserver/replica_read.go:221 [n1,s1,r64/1:/{Table/108-Max}] read completed
1.491ms -0.060ms structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"6603","blockBytesInCache":"6603","keyBytes":"14","valueBytes":"7","pointCount":"1","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","separatedPointCount":"0","separatedPointValueBytes":"0","separatedPointValueBytesFetched":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
1.658ms 0.747ms event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n1,client=127.0.0.1:56160,hostssl,user=root,txn=d9429de6] recording span to refresh: /Table/108/1/1/0
1.787ms 0.927ms event:ComponentStats{ID: {6ee68e59-4006-4414-a736-58526498c404 PROCESSOR 0 1 }, KV time: 837µs, KV contention time: 0µs, KV rows read: 1, KV bytes read: 11 B, KV gRPC calls: 1, MVCC step count (ext/int): 0/0, MVCC seek count (ext/int): 1/1, max memory allocated: 20 KiB, sql cpu time: 26µs, batches output: 1, rows output: 1}
1.816ms 0.030ms event:ComponentStats{ID: {00000000-0000-0000-0000-000000000000 UNSET 0 ? }}
1.720ms -0.097ms structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"6ee68e59-4006-4414-a736-58526498c404","type":"PROCESSOR","id":0,"sqlInstanceId":1,"region":""},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"12"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.000837351s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"6604"},"blockBytesInCache":{"valuePlusOne":"6604"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"8"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"},"usedStreamer":false},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000026433s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
1.801ms 0.081ms structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"00000000-0000-0000-0000-000000000000","type":"UNSET","id":0,"sqlInstanceId":0,"region":""},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"},"usedStreamer":false},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
1.873ms 1.014ms event:ComponentStats{ID: {6ee68e59-4006-4414-a736-58526498c404 FLOW 0 1 us-east-1}}
1.856ms -0.017ms structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"6ee68e59-4006-4414-a736-58526498c404","type":"FLOW","id":0,"sqlInstanceId":1,"region":"us-east-1"},"netRx":{"latency":{"valuePlusOne":"0s"},"waitTime":{"valuePlusOne":"0s"},"deserializationTime":{"valuePlusOne":"0s"},"tuplesReceived":{"valuePlusOne":"0"},"bytesReceived":{"valuePlusOne":"0"},"messagesReceived":{"valuePlusOne":"0"}},"netTx":{"tuplesSent":{"valuePlusOne":"0"},"bytesSent":{"valuePlusOne":"0"},"messagesSent":{"valuePlusOne":"0"}},"kv":{"bytesRead":{"valuePlusOne":"0"},"tuplesRead":{"valuePlusOne":"0"},"batchRequestsIssued":{"valuePlusOne":"0"},"kvTime":{"valuePlusOne":"0s"},"contentionTime":{"valuePlusOne":"0s"},"numInterfaceSteps":{"valuePlusOne":"0"},"numInternalSteps":{"valuePlusOne":"0"},"numInterfaceSeeks":{"valuePlusOne":"0"},"numInternalSeeks":{"valuePlusOne":"0"},"blockBytes":{"valuePlusOne":"0"},"blockBytesInCache":{"valuePlusOne":"0"},"keyBytes":{"valuePlusOne":"0"},"valueBytes":{"valuePlusOne":"0"},"pointCount":{"valuePlusOne":"0"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"0"},"rangeKeyCount":{"valuePlusOne":"0"},"rangeKeyContainedPoints":{"valuePlusOne":"0"},"rangeKeySkippedPoints":{"valuePlusOne":"0"},"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"},"usedStreamer":false},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"},"cpuTime":{"valuePlusOne":"0s"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"20481"},"maxDiskUsage":{"valuePlusOne":"1"},"consumedRu":{"valuePlusOne":"0"}}}
1.921ms 1.174ms event:sql/conn_executor_exec.go:1036 [n1,client=127.0.0.1:56160,hostssl,user=root] execution ends
1.947ms 0.026ms event:sql/conn_executor_exec.go:1036 [n1,client=127.0.0.1:56160,hostssl,user=root] rows affected: 1
2.044ms 0.097ms === operation:commit sql txn _verbose:1 node:1 client:127.0.0.1:56160 hostssl: user:root
2.082ms 0.135ms event:sql/conn_executor_exec.go:2832 [n1,client=127.0.0.1:56160,hostssl,user=root] AutoCommit. err: <nil>
--- FAIL: TestMultiRegionDataDriven/global_tables (31.71s)
Parameters: TAGS=bazel,gss
Same failure on other branches
- ccl/multiregionccl: TestMultiRegionDataDriven failed #98020 ccl/multiregionccl: TestMultiRegionDataDriven failed [A-kv-distribution A-kv-test-failure-complex C-bug C-test-failure O-robot T-kv branch-master skipped-test]
This test on roachdash | Improve this report!
Jira issue: CRDB-30624