ccl/multiregionccl: TestMultiRegionDataDriven failed #109949
Description
ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-22.2 @ 104d19503e192803e4969027d2cfabc0e645c3d8:
15.502ms 0.490ms === operation:flow _verbose:1 node:2 client:127.0.0.1:55442 user:root
16.009ms 0.507ms event:sql/colflow/vectorized_flow.go:241 [n2,client=127.0.0.1:55442,user=root] setting up vectorized flow
16.146ms 0.137ms event:sql/colflow/vectorized_flow.go:293 [n2,client=127.0.0.1:55442,user=root] vectorized flow setup succeeded
16.198ms 0.052ms event:sql/flowinfra/flow.go:387 [n2,client=127.0.0.1:55442,user=root] starting (0 processors, 0 startables) asynchronously
16.240ms 0.042ms event:sql/colflow/vectorized_flow.go:319 [n2,client=127.0.0.1:55442,user=root] running the batch flow coordinator in the flow's goroutine
36.179ms 19.939ms event:component:<flow_id:<ed0214ae-bc57-4ec3-8f7e-c1a101f70db8> type:FLOW id:0 sql_instance_id:2 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> num_gets:<> num_scans:<> num_reverse_scans:<> used_streamer:false > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_r_u:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_r_u:<> >
36.062ms -0.116ms structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"ed0214ae-bc57-4ec3-8f7e-c1a101f70db8","type":"FLOW","id":0,"sqlInstanceId":2},"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"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"},"usedStreamer":false},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRU":{"valuePlusOne":"0"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"20481"},"maxDiskUsage":{"valuePlusOne":"1"},"consumedRU":{"valuePlusOne":"0"}}}
16.253ms -19.810ms === operation:batch flow coordinator _unfinished:1 _verbose:1 node:2 client:127.0.0.1:55442 user:root cockroach.flowid:ed0214ae-bc57-4ec3-8f7e-c1a101f70db8 cockroach.processorid:0
34.301ms 18.048ms event:component:<flow_id:<ed0214ae-bc57-4ec3-8f7e-c1a101f70db8> type:PROCESSOR id:0 sql_instance_id:2 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<value_plus_one:12 > tuples_read:<value_plus_one:2 > batch_requests_issued:<value_plus_one:2 > kv_time:<value_plus_one:<nanos:16270585 > > contention_time:<value_plus_one:<nanos:1 > > num_interface_steps:<value_plus_one:1 > num_internal_steps:<value_plus_one:1 > num_interface_seeks:<value_plus_one:3 > num_internal_seeks:<value_plus_one:3 > num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > used_streamer:false > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_r_u:<value_plus_one:1 > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_r_u:<> >
34.708ms 0.407ms event:component:<flow_id:<00000000-0000-0000-0000-000000000000> type:UNSET id:0 sql_instance_id:0 > net_rx:<latency:<> wait_time:<> deserialization_time:<> tuples_received:<> bytes_received:<> messages_received:<> > net_tx:<tuples_sent:<> bytes_sent:<> messages_sent:<> > kv:<bytes_read:<> tuples_read:<> batch_requests_issued:<> kv_time:<> contention_time:<> num_interface_steps:<> num_internal_steps:<> num_interface_seeks:<> num_internal_seeks:<> num_gets:<> num_scans:<> num_reverse_scans:<> used_streamer:false > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_r_u:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_r_u:<> >
34.166ms -0.542ms structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"ed0214ae-bc57-4ec3-8f7e-c1a101f70db8","type":"PROCESSOR","id":0,"sqlInstanceId":2},"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.016270585s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"3"},"numInternalSeeks":{"valuePlusOne":"3"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"},"usedStreamer":false},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRU":{"valuePlusOne":"1"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRU":{"valuePlusOne":"0"}}}
34.590ms 0.425ms structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"00000000-0000-0000-0000-000000000000","type":"UNSET","id":0,"sqlInstanceId":0},"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"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"},"usedStreamer":false},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"0"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRU":{"valuePlusOne":"0"}},"output":{"numBatches":{"valuePlusOne":"0"},"numTuples":{"valuePlusOne":"0"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRU":{"valuePlusOne":"0"}}}
16.337ms -18.253ms === operation:colbatchscan _unfinished:1 _verbose:1 node:2 client:127.0.0.1:55442 user:root
16.337ms 0.000ms [txn coordinator send: {count: 1, duration 12ms}]
16.337ms 0.000ms [dist sender send: {count: 1, duration 8ms}]
16.337ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
19.972ms 3.635ms event:sql/row/kv_batch_fetcher.go:528 [n2,client=127.0.0.1:55442,user=root] Scan /Table/108/1/1/0
20.192ms 0.220ms === operation:txn coordinator send _verbose:1 node:2 client:127.0.0.1:55442 user:root txnID:370a0897-1079-4a94-8837-21d42a3ad3c7
20.192ms 0.000ms [dist sender send: {count: 1, duration 8ms}]
20.192ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
20.293ms 0.102ms === operation:dist sender send _verbose:1 node:2 client:127.0.0.1:55442 user:root txn:370a0897
20.293ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
20.418ms 0.125ms event:kv/kvclient/kvcoord/range_iter.go:183 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] querying next range at /Table/108/1/1/0
23.318ms 2.899ms event:kv/kvclient/kvcoord/range_iter.go:216 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] key: /Table/108/1/1/0, desc: r53:/{Table/108-Max} [(n1,s1):1, (n3,s3):9, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):10NON_VOTER, next=11, gen=25]
23.518ms 0.200ms event:kv/kvclient/kvcoord/dist_sender.go:1991 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] routing to nearest replica; leaseholder not required
23.816ms 0.298ms event:kv/kvclient/kvcoord/dist_sender.go:2049 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] r53: sending batch 1 Get to (n2,s2):5
23.877ms 0.060ms event:rpc/nodedialer/nodedialer.go:159 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] sending request to local client
23.934ms 0.057ms === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:2 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: 370a0897], [can-forward-ts]
24.214ms 0.280ms event:server/node.go:1090 [n2] node received request: 1 Get
24.435ms 0.221ms event:kv/kvserver/store_send.go:166 [n2,s2] executing Get [/Table/108/1/1/0,/Min), [txn: 370a0897], [can-forward-ts]
24.774ms 0.340ms event:kv/kvserver/replica_send.go:174 [n2,s2,r53/5:/{Table/108-Max}] read-only path
25.162ms 0.388ms event:kv/kvserver/concurrency/concurrency_manager.go:207 [n2,s2,r53/5:/{Table/108-Max}] sequencing request
25.342ms 0.180ms event:kv/kvserver/concurrency/concurrency_manager.go:288 [n2,s2,r53/5:/{Table/108-Max}] acquiring latches
25.434ms 0.092ms event:kv/kvserver/concurrency/concurrency_manager.go:332 [n2,s2,r53/5:/{Table/108-Max}] scanning lock table for conflicting locks
25.817ms 0.383ms event:kv/kvserver/replica_read.go:269 [n2,s2,r53/5:/{Table/108-Max}] executing read-only batch
26.037ms 0.219ms event:kv/kvserver/replica_evaluate.go:544 [n2,s2,r53/5:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=370a0897 key=/Min pri=0.01040101 epo=0 ts=1693637955.975864617,0 min=1693637955.975864617,0 seq=0} lock=false stat=PENDING rts=1693637955.975864617,0 wto=false gul=1693637956.475864617,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1693637929737565438 > > , err=<nil>
26.151ms 0.114ms event:scan stats: stepped 0 times (0 internal); seeked 2 times (2 internal); block-bytes: (total 11 KiB, cached 11 KiB); points: (count 2 , key-bytes 27 B, value-bytes 87 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
26.548ms 0.397ms event:kv/kvserver/replica_read.go:204 [n2,s2,r53/5:/{Table/108-Max}] read completed
26.662ms 0.114ms event:kv/kvserver/replica_send.go:314 [n2,s2,r53/5:/{Table/108-Max}] client had stale range info; returning an update
26.062ms -0.600ms structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"11398","blockBytesInCache":"11398","keyBytes":"27","valueBytes":"87","pointCount":"2","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
27.247ms 3.370ms event:kv/kvclient/kvcoord/dist_sender.go:2172 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] received updated range info: [desc: r53:/{Table/108-Max} [(n1,s1):1, (n3,s3):9, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):10NON_VOTER, next=11, gen=25], lease: repl=(n2,s2):5 seq=39 start=1693637955.927108872,0 epo=1 pro=1693637955.950461886,0, closed_timestamp_policy: LEAD_FOR_GLOBAL_READS]
27.393ms 0.146ms event:kv/kvclient/rangecache/range_cache.go:938 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] evict cached descriptor: desc=desc:r53:/{Table/108-Max} [(n1,s1):1, (n3,s3):9, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):10NON_VOTER, next=11, gen=25], lease:repl=(n1,s1):1 seq=37 start=1693637953.719250519,0 epo=1 pro=1693637953.738226938,0
27.461ms 0.068ms event:kv/kvclient/rangecache/range_cache.go:555 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] evicting cached range descriptor with 1 replacements
27.717ms 0.256ms event:kv/kvclient/rangecache/range_cache.go:1107 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] clearing entries overlapping r53:/{Table/108-Max} [(n1,s1):1, (n3,s3):9, (n2,s2):5, (n5,s5):6NON_VOTER, (n4,s4):10NON_VOTER, next=11, gen=25]
28.077ms 7.885ms event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:572 [n2,client=127.0.0.1:55442,user=root,txn=370a0897] recording span to refresh: /Table/108/1/1/0
36.637ms 21.625ms event:sql/conn_executor_exec.go:694 [n2,client=127.0.0.1:55442,user=root] execution ends
36.676ms 0.039ms event:sql/conn_executor_exec.go:694 [n2,client=127.0.0.1:55442,user=root] rows affected: 1
41.692ms 5.016ms === operation:commit sql txn _verbose:1 node:2 client:127.0.0.1:55442 user:root
62.028ms 25.352ms event:sql/conn_executor_exec.go:2191 [n2,client=127.0.0.1:55442,user=root] AutoCommit. err: <nil>
--- FAIL: TestMultiRegionDataDriven/global_tables (70.52s)
Parameters: TAGS=bazel,gss,deadlock
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-31175
Metadata
Metadata
Assignees
Labels
Testing tools and infrastructureCode not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior.Broken test (automatically or manually discovered).Originated from a bot.KV TeamUsed to mark GA and release blockers, technical advisories, and bugs for 22.2Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked.