Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ccl/multiregionccl: TestMultiRegionDataDriven failed #109949

Closed
cockroach-teamcity opened this issue Sep 2, 2023 · 4 comments · Fixed by #110053
Closed

ccl/multiregionccl: TestMultiRegionDataDriven failed #109949

cockroach-teamcity opened this issue Sep 2, 2023 · 4 comments · Fixed by #110053
Assignees
@kvoli
Labels
A-testing Testing tools and infrastructure branch-release-22.2 Used to mark GA and release blockers, technical advisories, and bugs for 22.2 C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-kv KV Team
Milestone
22.2

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Sep 2, 2023 •
edited by cockroach-jira-scripts
Loading

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

Help

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

Same failure on other branches

/cc @cockroachdb/multiregion

This test on roachdash | Improve this report!

Jira issue: CRDB-31175
@cockroach-teamcity cockroach-teamcity added branch-release-22.2 Used to mark GA and release blockers, technical advisories, and bugs for 22.2 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. labels Sep 2, 2023
@cockroach-teamcity cockroach-teamcity added this to the 22.2 milestone Sep 2, 2023
@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-22.2 @ 8247588204126b27473f1aa2f0f20534364187d0:

             5.684ms      0.067ms    event:sql/conn_executor_exec.go:694 [n3,client=127.0.0.1:56122,user=root] will distribute plan: false
            21.232ms     15.548ms    event:sql/conn_executor_exec.go:694 [n3,client=127.0.0.1:56122,user=root] executing after 0 retries, last retry reason: <nil>
            22.285ms      1.052ms    event:sql/conn_executor_exec.go:694 [n3,client=127.0.0.1:56122,user=root] execution starts: distributed engine
            22.359ms      0.075ms    event:sql/distsql_running.go:1749 [n3,client=127.0.0.1:56122,user=root] creating DistSQL plan with isLocal=true
            22.776ms      0.416ms    event:sql/distsql_running.go:664 [n3,client=127.0.0.1:56122,user=root] running DistSQL plan
            23.029ms      0.253ms        === operation:flow _verbose:1 node:3 client:127.0.0.1:56122 user:root
            23.349ms      0.321ms        event:sql/colflow/vectorized_flow.go:241 [n3,client=127.0.0.1:56122,user=root] setting up vectorized flow
            23.495ms      0.146ms        event:sql/colflow/vectorized_flow.go:293 [n3,client=127.0.0.1:56122,user=root] vectorized flow setup succeeded
            23.546ms      0.051ms        event:sql/flowinfra/flow.go:387 [n3,client=127.0.0.1:56122,user=root] starting (0 processors, 0 startables) asynchronously
            23.622ms      0.077ms        event:sql/colflow/vectorized_flow.go:319 [n3,client=127.0.0.1:56122,user=root] running the batch flow coordinator in the flow's goroutine
            45.454ms     21.832ms        event:component:<flow_id:<5d6b8572-be43-4544-b7ac-5762331b557e> type:FLOW id:0 sql_instance_id:3 > 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:<> >
            45.319ms     -0.135ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"5d6b8572-be43-4544-b7ac-5762331b557e","type":"FLOW","id":0,"sqlInstanceId":3},"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"}}}
            23.638ms    -21.681ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:3 client:127.0.0.1:56122 user:root cockroach.flowid:5d6b8572-be43-4544-b7ac-5762331b557e cockroach.processorid:0
            44.265ms     20.627ms        event:component:<flow_id:<5d6b8572-be43-4544-b7ac-5762331b557e> type:PROCESSOR id:0 sql_instance_id:3 > 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:19696747 > > 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:<> >
            44.375ms      0.110ms        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:<> >
            44.121ms     -0.254ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"5d6b8572-be43-4544-b7ac-5762331b557e","type":"PROCESSOR","id":0,"sqlInstanceId":3},"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.019696747s"},"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"}}}
            44.286ms      0.164ms        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"}}}
            24.139ms    -20.147ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:3 client:127.0.0.1:56122 user:root
            24.139ms      0.000ms        [txn coordinator send: {count: 1, duration 18ms}]
            24.139ms      0.000ms        [dist sender send: {count: 1, duration 17ms}]
            24.139ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 1, duration 14ms}]
            24.933ms      0.794ms        event:sql/row/kv_batch_fetcher.go:528 [n3,client=127.0.0.1:56122,user=root] Scan /Table/108/1/1/0
            24.987ms      0.054ms            === operation:txn coordinator send _verbose:1 node:3 client:127.0.0.1:56122 user:root txnID:ee2162da-4696-4922-b5de-83ba8be70ae8
            24.987ms      0.000ms            [dist sender send: {count: 1, duration 17ms}]
            24.987ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 1, duration 14ms}]
            25.105ms      0.118ms                === operation:dist sender send _verbose:1 node:3 client:127.0.0.1:56122 user:root txn:ee2162da
            25.105ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 1, duration 14ms}]
            25.233ms      0.127ms                event:kv/kvclient/kvcoord/range_iter.go:183 [n3,client=127.0.0.1:56122,user=root,txn=ee2162da] querying next range at /Table/108/1/1/0
            25.377ms      0.144ms                event:kv/kvclient/kvcoord/range_iter.go:216 [n3,client=127.0.0.1:56122,user=root,txn=ee2162da] key: /Table/108/1/1/0, desc: r53:/{Table/108-Max} [(n1,s1):1, (n3,s3):9, (n2,s2):5, (n4,s4):6NON_VOTER, (n5,s5):11NON_VOTER, next=12, gen=27]
            26.025ms      0.649ms                event:kv/kvclient/kvcoord/dist_sender.go:1991 [n3,client=127.0.0.1:56122,user=root,txn=ee2162da] routing to nearest replica; leaseholder not required
            27.396ms      1.370ms                event:kv/kvclient/kvcoord/dist_sender.go:2049 [n3,client=127.0.0.1:56122,user=root,txn=ee2162da] r53: sending batch 1 Get to (n3,s3):9
            27.673ms      0.278ms                event:rpc/nodedialer/nodedialer.go:159 [n3,client=127.0.0.1:56122,user=root,txn=ee2162da] sending request to local client
            27.732ms      0.059ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:3 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: ee2162da], [can-forward-ts]
            28.308ms      0.576ms                    event:server/node.go:1090 [n3] node received request: 1 Get
            28.854ms      0.546ms                    event:kv/kvserver/store_send.go:166 [n3,s3] executing Get [/Table/108/1/1/0,/Min), [txn: ee2162da], [can-forward-ts]
            36.191ms      7.337ms                    event:kv/kvserver/replica_send.go:174 [n3,s3,r53/9:/{Table/108-Max}] read-only path
            36.378ms      0.186ms                    event:kv/kvserver/concurrency/concurrency_manager.go:207 [n3,s3,r53/9:/{Table/108-Max}] sequencing request
            36.434ms      0.056ms                    event:kv/kvserver/concurrency/concurrency_manager.go:288 [n3,s3,r53/9:/{Table/108-Max}] acquiring latches
            36.512ms      0.078ms                    event:kv/kvserver/concurrency/concurrency_manager.go:332 [n3,s3,r53/9:/{Table/108-Max}] scanning lock table for conflicting locks
            36.780ms      0.268ms                    event:kv/kvserver/replica_read.go:269 [n3,s3,r53/9:/{Table/108-Max}] executing read-only batch
            37.755ms      0.975ms                    event:kv/kvserver/replica_evaluate.go:544 [n3,s3,r53/9:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=ee2162da key=/Min pri=0.02206387 epo=0 ts=1693811881.098229794,0 min=1693811881.098229794,0 seq=0} lock=false stat=PENDING rts=1693811881.098229794,0 wto=false gul=1693811881.598229794,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1693811857910906774 > > , err=<nil>
            37.875ms      0.120ms                    event:scan stats: stepped 0 times (0 internal); seeked 2 times (2 internal); block-bytes: (total 26 KiB, cached 26 KiB); points: (count 2, key-bytes 42 B, value-bytes 20 B, tombstoned: 0) ranges: (count 0), (contained-points 0, skipped-points 0) evaluated requests: 1 gets, 0 scans, 0 reverse scans
            41.349ms      3.473ms                    event:kv/kvserver/replica_read.go:204 [n3,s3,r53/9:/{Table/108-Max}] read completed
            37.788ms     -3.561ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"27174","blockBytesInCache":"27174","keyBytes":"42","valueBytes":"20","pointCount":"2","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
            43.103ms     18.116ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:572 [n3,client=127.0.0.1:56122,user=root,txn=ee2162da] recording span to refresh: /Table/108/1/1/0
            45.975ms     23.200ms    event:sql/conn_executor_exec.go:694 [n3,client=127.0.0.1:56122,user=root] execution ends
            46.017ms      0.042ms    event:sql/conn_executor_exec.go:694 [n3,client=127.0.0.1:56122,user=root] rows affected: 1
            46.657ms      0.640ms        === operation:commit sql txn _verbose:1 node:3 client:127.0.0.1:56122 user:root
            47.047ms      1.030ms    event:sql/conn_executor_exec.go:2191 [n3,client=127.0.0.1:56122,user=root] AutoCommit. err: <nil>
    --- FAIL: TestMultiRegionDataDriven/global_tables (69.40s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-22.2 @ eba3e91b9fe08273c611b26faa364b8d077fd5ee:

            34.308ms      0.178ms    event:sql/conn_executor_exec.go:694 [n5,client=127.0.0.1:55840,user=root] execution starts: distributed engine
            34.924ms      0.616ms    event:sql/distsql_running.go:1749 [n5,client=127.0.0.1:55840,user=root] creating DistSQL plan with isLocal=true
            34.981ms      0.057ms    event:sql/distsql_running.go:664 [n5,client=127.0.0.1:55840,user=root] running DistSQL plan
            35.018ms      0.037ms        === operation:flow _verbose:1 node:5 client:127.0.0.1:55840 user:root
            35.473ms      0.455ms        event:sql/colflow/vectorized_flow.go:241 [n5,client=127.0.0.1:55840,user=root] setting up vectorized flow
            35.723ms      0.249ms        event:sql/colflow/vectorized_flow.go:293 [n5,client=127.0.0.1:55840,user=root] vectorized flow setup succeeded
            35.994ms      0.271ms        event:sql/flowinfra/flow.go:387 [n5,client=127.0.0.1:55840,user=root] starting (0 processors, 0 startables) asynchronously
            36.441ms      0.448ms        event:sql/colflow/vectorized_flow.go:319 [n5,client=127.0.0.1:55840,user=root] running the batch flow coordinator in the flow's goroutine
            49.043ms     12.602ms        event:component:<flow_id:<7d8c7c41-cc6e-4585-b12f-1a82c13fec10> type:FLOW id:0 sql_instance_id:5 > 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:<> >
            48.736ms     -0.308ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"7d8c7c41-cc6e-4585-b12f-1a82c13fec10","type":"FLOW","id":0,"sqlInstanceId":5},"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"}}}
            36.959ms    -11.776ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:5 client:127.0.0.1:55840 user:root cockroach.flowid:7d8c7c41-cc6e-4585-b12f-1a82c13fec10 cockroach.processorid:0
            47.206ms     10.247ms        event:component:<flow_id:<7d8c7c41-cc6e-4585-b12f-1a82c13fec10> type:PROCESSOR id:0 sql_instance_id:5 > 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:9439110 > > 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:<> >
            47.488ms      0.282ms        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:<> >
            47.014ms     -0.475ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"7d8c7c41-cc6e-4585-b12f-1a82c13fec10","type":"PROCESSOR","id":0,"sqlInstanceId":5},"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.009439110s"},"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"}}}
            47.227ms      0.214ms        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"}}}
            37.250ms     -9.978ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:5 client:127.0.0.1:55840 user:root
            37.250ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 2, duration 10ms}]
            37.250ms      0.000ms        [txn coordinator send: {count: 1, duration 8ms}]
            37.250ms      0.000ms        [dist sender send: {count: 1, duration 7ms}]
            37.874ms      0.625ms        event:sql/row/kv_batch_fetcher.go:528 [n5,client=127.0.0.1:55840,user=root] Scan /Table/108/1/1/0
            37.943ms      0.069ms            === operation:txn coordinator send _verbose:1 node:5 client:127.0.0.1:55840 user:root txnID:2d4192c6-9a73-4db6-aa28-ead7ecbc312c
            37.943ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 2, duration 10ms}]
            37.943ms      0.000ms            [dist sender send: {count: 1, duration 7ms}]
            38.171ms      0.228ms                === operation:dist sender send _verbose:1 node:5 client:127.0.0.1:55840 user:root txn:2d4192c6
            38.171ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 2, duration 10ms}]
            38.446ms      0.275ms                event:kv/kvclient/kvcoord/range_iter.go:183 [n5,client=127.0.0.1:55840,user=root,txn=2d4192c6] querying next range at /Table/108/1/1/0
            38.639ms      0.193ms                event:kv/kvclient/kvcoord/range_iter.go:216 [n5,client=127.0.0.1:55840,user=root,txn=2d4192c6] key: /Table/108/1/1/0, desc: r53:/{Table/108-Max} [(n1,s1):1, (n3,s3):10, (n2,s2):5, (n4,s4):7NON_VOTER, next=13, gen=30]
            39.069ms      0.430ms                event:kv/kvclient/kvcoord/dist_sender.go:1991 [n5,client=127.0.0.1:55840,user=root,txn=2d4192c6] routing to nearest replica; leaseholder not required
            39.441ms      0.372ms                event:kv/kvclient/kvcoord/dist_sender.go:2049 [n5,client=127.0.0.1:55840,user=root,txn=2d4192c6] r53: sending batch 1 Get to (n2,s2):5
            39.506ms      0.065ms                event:rpc/nodedialer/nodedialer.go:163 [n5,client=127.0.0.1:55840,user=root,txn=2d4192c6] sending request to 127.0.0.1:37743
            39.539ms      0.033ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:5 client:127.0.0.1:55840 user:root txn:2d4192c6 span.kind:client node:5
            40.097ms      0.559ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:2 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: 2d4192c6], [can-forward-ts]
            40.168ms      0.071ms                    event:server/node.go:1090 [n2] node received request: 1 Get
            40.686ms      0.518ms                    event:kv/kvserver/store_send.go:166 [n2,s2] executing Get [/Table/108/1/1/0,/Min), [txn: 2d4192c6], [can-forward-ts]
            41.500ms      0.814ms                    event:kv/kvserver/replica_send.go:174 [n2,s2,r53/5:/{Table/108-Max}] read-only path
            42.290ms      0.790ms                    event:kv/kvserver/concurrency/concurrency_manager.go:207 [n2,s2,r53/5:/{Table/108-Max}] sequencing request
            42.327ms      0.037ms                    event:kv/kvserver/concurrency/concurrency_manager.go:288 [n2,s2,r53/5:/{Table/108-Max}] acquiring latches
            42.387ms      0.059ms                    event:kv/kvserver/concurrency/concurrency_manager.go:332 [n2,s2,r53/5:/{Table/108-Max}] scanning lock table for conflicting locks
            43.140ms      0.753ms                    event:kv/kvserver/replica_follower_read.go:105 [n2,s2,r53/5:/{Table/108-Max}] serving via follower read; query timestamp below closed timestamp by 64.906063ms
            43.214ms      0.074ms                    event:kv/kvserver/replica_read.go:269 [n2,s2,r53/5:/{Table/108-Max}] executing read-only batch
            43.446ms      0.232ms                    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=2d4192c6 key=/Min pri=0.00993498 epo=0 ts=1693898614.196785532,0 min=1693898614.196785532,0 seq=0} lock=false stat=PENDING rts=1693898614.196785532,0 wto=false gul=1693898614.696785532,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1693898588716277294 > > , err=<nil>
            43.547ms      0.102ms                    event:scan stats: stepped 0 times (0 internal); seeked 2 times (2 internal); block-bytes: (total 31 KiB, cached 31 KiB); points: (count 2, key-bytes 36 B, value-bytes 30 B, tombstoned: 0) ranges: (count 0), (contained-points 0, skipped-points 0) evaluated requests: 1 gets, 0 scans, 0 reverse scans
            44.146ms      0.598ms                    event:kv/kvserver/replica_read.go:204 [n2,s2,r53/5:/{Table/108-Max}] read completed
            43.473ms     -0.672ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"31572","blockBytesInCache":"31572","keyBytes":"36","valueBytes":"30","pointCount":"2","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
            45.974ms      8.031ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:572 [n5,client=127.0.0.1:55840,user=root,txn=2d4192c6] recording span to refresh: /Table/108/1/1/0
            49.800ms     14.819ms    event:sql/conn_executor_exec.go:694 [n5,client=127.0.0.1:55840,user=root] execution ends
            49.840ms      0.041ms    event:sql/conn_executor_exec.go:694 [n5,client=127.0.0.1:55840,user=root] rows affected: 1
            50.991ms      1.151ms        === operation:commit sql txn _verbose:1 node:5 client:127.0.0.1:55840 user:root
            60.944ms     11.104ms    event:sql/conn_executor_exec.go:2191 [n5,client=127.0.0.1:55840,user=root] AutoCommit. err: <nil>
    --- FAIL: TestMultiRegionDataDriven/global_tables (70.26s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@rafiss rafiss added the T-kv KV Team label Sep 6, 2023
@kvoli kvoli self-assigned this Sep 6, 2023
@kvoli kvoli linked a pull request Sep 6, 2023 that will close this issue
release-22.2: ccl/multiregionccl: disable transfers in multiregion test #110053
Merged
@kvoli
Copy link
Collaborator

kvoli commented Sep 6, 2023

Closed on #110053.

@kvoli kvoli closed this as completed Sep 6, 2023
@kvoli kvoli added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. A-testing Testing tools and infrastructure labels Sep 6, 2023
@exalate-issue-sync exalate-issue-sync bot removed C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. A-testing Testing tools and infrastructure labels Sep 6, 2023
@kvoli
Copy link
Collaborator

kvoli commented Sep 6, 2023

Sanity checking this wasn't a different issue, on release-22.2(9869f34) with #110053 merged:

dev test pkg/ccl/multiregionccl -f TestMultiRegionDataDriven/global_tables  -v --stress
...
1602 runs so far, 0 failures, over 41m0s

@kvoli kvoli added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. A-testing Testing tools and infrastructure labels Sep 7, 2023
@github-project-automation github-project-automation bot moved this to Closed in KV Aug 28, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kvoli kvoli

Labels
A-testing Testing tools and infrastructure branch-release-22.2 Used to mark GA and release blockers, technical advisories, and bugs for 22.2 C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-kv KV Team
Projects
No open projects
KV
Archived in project
Milestone
22.2
Development

Successfully merging a pull request may close this issue.

release-22.2: ccl/multiregionccl: disable transfers in multiregion test kvoli/cockroach
3 participants
@rafiss @cockroach-teamcity @kvoli