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 #101520

Closed
cockroach-teamcity opened this issue Apr 14, 2023 · 4 comments
Closed

ccl/multiregionccl: TestMultiRegionDataDriven failed #101520

cockroach-teamcity opened this issue Apr 14, 2023 · 4 comments
Assignees
@chengxiong-ruan
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Milestone
23.1

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Apr 14, 2023 •
edited by cockroach-jira-scripts
Loading

ccl/multiregionccl.TestMultiRegionDataDriven failed with artifacts on release-23.1.0 @ 5e9f0c062e6b166b76148f7a6e10c2f509658d37:

             4.873ms      0.062ms        event:sql/flowinfra/flow.go:442 [n1,client=127.0.0.1:46960,user=root] starting (0 processors, 0 startables) asynchronously
             4.924ms      0.051ms        event:sql/colflow/vectorized_flow.go:325 [n1,client=127.0.0.1:46960,user=root] running the batch flow coordinator in the flow's goroutine
            12.459ms      7.535ms        event:component:<flow_id:<7385a3ad-2f74-4920-9a2e-6f82cf5002a7> type:FLOW id:0 sql_instance_id:1 > 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:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_ru:<> >
            12.286ms     -0.172ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"7385a3ad-2f74-4920-9a2e-6f82cf5002a7","type":"FLOW","id":0,"sqlInstanceId":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"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"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"}}}
             4.972ms     -7.314ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:1 client:127.0.0.1:46960 user:root cockroach.flowid:7385a3ad-2f74-4920-9a2e-6f82cf5002a7 cockroach.processorid:0
            11.336ms      6.364ms        event:component:<flow_id:<7385a3ad-2f74-4920-9a2e-6f82cf5002a7> type:PROCESSOR id:0 sql_instance_id:1 > 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:5724270 > > 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:2 > num_internal_seeks:<value_plus_one:2 > block_bytes:<value_plus_one:3787 > block_bytes_in_cache:<value_plus_one:3787 > key_bytes:<value_plus_one:15 > value_bytes:<value_plus_one:15 > point_count:<value_plus_one:2 > points_covered_by_range_tombstones:<value_plus_one:1 > range_key_count:<value_plus_one:1 > range_key_contained_points:<value_plus_one:1 > range_key_skipped_points:<value_plus_one:1 > kv_cpu_time:<> num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_ru:<value_plus_one:1 > cpu_time:<value_plus_one:<nanos:459268 > > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            11.597ms      0.261ms        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:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            11.135ms     -0.461ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"7385a3ad-2f74-4920-9a2e-6f82cf5002a7","type":"PROCESSOR","id":0,"sqlInstanceId":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":"12"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.005724270s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"3787"},"blockBytesInCache":{"valuePlusOne":"3787"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"15"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000459268s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
            11.392ms      0.257ms        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"},"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"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"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"}}}
             5.100ms     -6.292ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:1 client:127.0.0.1:46960 user:root
             5.100ms      0.000ms        [txn coordinator send: {count: 1, duration 5ms}]
             5.100ms      0.000ms        [dist sender send: {count: 1, duration 4ms}]
             5.100ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             5.547ms      0.447ms        event:sql/row/kv_batch_fetcher.go:475 [n1,client=127.0.0.1:46960,user=root] Scan /Table/108/1/1/0
             5.629ms      0.081ms            === operation:txn coordinator send _verbose:1 node:1 client:127.0.0.1:46960 user:root txnID:a8f00682-00a1-4053-bcff-edec6f0c9546
             5.629ms      0.000ms            [dist sender send: {count: 1, duration 4ms}]
             5.629ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             5.781ms      0.152ms                === operation:dist sender send _verbose:1 node:1 client:127.0.0.1:46960 user:root txn:a8f00682
             5.781ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             5.941ms      0.160ms                event:kv/kvclient/kvcoord/range_iter.go:188 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] querying next range at /Table/108/1/1/0
             6.147ms      0.205ms                event:kv/kvclient/kvcoord/range_iter.go:225 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] key: /Table/108/1/1/0, desc: r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25]
             6.285ms      0.139ms                event:kv/kvclient/kvcoord/dist_sender.go:2051 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] routing to nearest replica; leaseholder not required
             6.887ms      0.602ms                event:kv/kvclient/kvcoord/dist_sender.go:2109 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] r63: sending batch 1 Get to (n1,s1):1
             6.968ms      0.081ms                event:rpc/nodedialer/nodedialer.go:157 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] sending request to local client
             7.030ms      0.061ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: a8f00682], [can-forward-ts]
             7.189ms      0.159ms                    event:server/node.go:1171 [n1] node received request: 1 Get
             7.394ms      0.205ms                    event:kv/kvserver/store_send.go:167 [n1,s1] executing Get [/Table/108/1/1/0,/Min), [txn: a8f00682], [can-forward-ts]
             7.573ms      0.179ms                    event:kv/kvserver/replica_send.go:179 [n1,s1,r63/1:/{Table/108-Max}] read-only path
             7.691ms      0.119ms                    event:kv/kvserver/concurrency/concurrency_manager.go:194 [n1,s1,r63/1:/{Table/108-Max}] sequencing request
             7.749ms      0.058ms                    event:kv/kvserver/concurrency/concurrency_manager.go:275 [n1,s1,r63/1:/{Table/108-Max}] acquiring latches
             7.838ms      0.089ms                    event:kv/kvserver/concurrency/concurrency_manager.go:319 [n1,s1,r63/1:/{Table/108-Max}] scanning lock table for conflicting locks
             8.109ms      0.270ms                    event:kv/kvserver/replica_follower_read.go:127 [n1,s1,r63/1:/{Table/108-Max}] serving via follower read; query timestamp below closed timestamp by 141.121822ms
             8.292ms      0.183ms                    event:kv/kvserver/replica_read.go:296 [n1,s1,r63/1:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: a8f00682], [can-forward-ts]); scanning lock table first to detect conflicts
             8.432ms      0.140ms                    event:kv/kvserver/replica_read.go:113 [n1,s1,r63/1:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
             8.562ms      0.130ms                    event:kv/kvserver/replica_read.go:408 [n1,s1,r63/1:/{Table/108-Max}] executing read-only batch
             8.957ms      0.395ms                    event:kv/kvserver/replica_evaluate.go:550 [n1,s1,r63/1:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=a8f00682 key=/Min pri=0.00520204 epo=0 ts=1681452512.813048908,0 min=1681452512.813048908,0 seq=0} lock=false stat=PENDING rts=1681452512.813048908,0 wto=false gul=1681452513.313048908,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1681452499775152626 > > , err=<nil>
             9.078ms      0.121ms                    event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 3.7 KiB, cached 3.7 KiB); points: (count 1 , key-bytes 14 B, value-bytes 14 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
             9.257ms      0.179ms                    event:kv/kvserver/replica_read.go:221 [n1,s1,r63/1:/{Table/108-Max}] read completed
             9.325ms      0.068ms                    event:kv/kvserver/replica_send.go:321 [n1,s1,r63/1:/{Table/108-Max}] client had stale range info; returning an update
             8.993ms     -0.332ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"3786","blockBytesInCache":"3786","keyBytes":"14","valueBytes":"14","pointCount":"1","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","separatedPointCount":"0","separatedPointValueBytes":"0","separatedPointValueBytesFetched":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
             9.818ms      2.849ms                event:kv/kvclient/kvcoord/dist_sender.go:2238 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] received updated range info: [desc: r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25], lease: repl=(n2,s2):5 seq=3 start=1681452512.683300499,0 epo=1 pro=1681452512.706779630,0, closed_timestamp_policy: LEAD_FOR_GLOBAL_READS]
             9.990ms      0.172ms                event:kv/kvclient/rangecache/range_cache.go:1083 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] evict cached descriptor: desc=desc:r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25], lease:repl=(n2,s2):5 seq=2 start=1681452512.683300499,0 exp=1681452518.681706531,0 pro=1681452512.681706531,0
            10.046ms      0.056ms                event:kv/kvclient/rangecache/range_cache.go:594 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] evicting cached range descriptor with 1 replacements
            10.123ms      0.077ms                event:kv/kvclient/rangecache/range_cache.go:1252 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] clearing entries overlapping r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25]
            10.408ms      4.779ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] recording span to refresh: /Table/108/1/1/0
            12.773ms      8.352ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] execution ends
            12.824ms      0.050ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] rows affected: 1
            14.269ms      1.445ms        === operation:commit sql txn _verbose:1 node:1 client:127.0.0.1:46960 user:root
            14.697ms      1.873ms    event:sql/conn_executor_exec.go:2724 [n1,client=127.0.0.1:46960,user=root] AutoCommit. err: <nil>
    --- FAIL: TestMultiRegionDataDriven/global_tables (63.31s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

/cc @cockroachdb/sql-schema

This test on roachdash | Improve this report!

Jira issue: CRDB-26987
@cockroach-teamcity cockroach-teamcity added branch-release-23.1.0 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Apr 14, 2023
@cockroach-teamcity cockroach-teamcity added this to the 23.1 milestone Apr 14, 2023
@blathers-crl blathers-crl bot added the T-sql-schema-deprecated Use T-sql-foundations instead label Apr 14, 2023
@cockroach-teamcity cockroach-teamcity mentioned this issue Apr 15, 2023
Closed
@chengxiong-ruan
Copy link
Contributor

the full error message:

datadriven_test.go:132: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/1456/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/global_tables:24:
         SELECT * FROM db.global WHERE k = 1
        expected:
        served locally: true
        served via follower read: false
        
        found:
        not a match, trace:
             0.000ms      0.000ms    === operation:traced statement _verbose:1 node:1 client:127.0.0.1:46960 user:root
             0.000ms      0.000ms    [flow: {count: 1, duration 8ms}]
             0.000ms      0.000ms    [colbatchscan: {count: 1, duration 7ms}]
             0.000ms      0.000ms    [batch flow coordinator: {count: 1, duration 7ms}]
             0.000ms      0.000ms    [txn coordinator send: {count: 1, duration 5ms}]
             0.000ms      0.000ms    [dist sender send: {count: 1, duration 4ms}]
             0.000ms      0.000ms    [optimizer: {count: 1, duration 4ms}]
             0.000ms      0.000ms    [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             0.000ms      0.000ms    [commit sql txn: {count: 1, duration 291µs}]
             0.089ms      0.089ms        === operation:optimizer _verbose:1 node:1 client:127.0.0.1:46960 user:root
             0.214ms      0.125ms        event:sql/plan_opt.go:389 [n1,client=127.0.0.1:46960,user=root] query cache miss
             0.263ms      0.049ms        event:sql/opt/optbuilder/builder.go:201 [n1,client=127.0.0.1:46960,user=root] optbuilder start
             0.480ms      0.217ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n1,client=127.0.0.1:46960,user=root] descriptorVersionState.incRefCount: 100("defaultdb") ver=1:1681452788.512207414,0, refcount=1
             0.880ms      0.400ms        event:sql/catalog/descs/descriptor.go:137 [n1,client=127.0.0.1:46960,user=root] looking up descriptors for ids [100]
             1.076ms      0.196ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n1,client=127.0.0.1:46960,user=root] descriptorVersionState.incRefCount: 104("db") ver=1:1681452797.870155005,0, refcount=1
             1.933ms      0.857ms        event:sql/catalog/descs/descriptor.go:137 [n1,client=127.0.0.1:46960,user=root] looking up descriptors for ids [104]
             2.005ms      0.072ms        event:sql/catalog/descs/descriptor.go:137 [n1,client=127.0.0.1:46960,user=root] looking up descriptors for ids [105]
             2.257ms      0.252ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n1,client=127.0.0.1:46960,user=root] descriptorVersionState.incRefCount: 105("public") ver=1:1681452786.773546468,0, refcount=1
             2.693ms      0.437ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n1,client=127.0.0.1:46960,user=root] descriptorVersionState.incRefCount: 108("global") ver=1:1681452800.392605536,0, refcount=1
             3.190ms      0.497ms        event:sql/catalog/descs/descriptor.go:137 [n1,client=127.0.0.1:46960,user=root] looking up descriptors for ids [108]
             3.494ms      0.304ms        event:sql/opt/optbuilder/builder.go:247 [n1,client=127.0.0.1:46960,user=root] optbuilder finish
             3.547ms      0.053ms        event:sql/opt/xform/optimizer.go:240 [n1,client=127.0.0.1:46960,user=root] optimize start
             3.654ms      0.107ms        event:sql/opt/xform/optimizer.go:289 [n1,client=127.0.0.1:46960,user=root] optimize finish
             3.723ms      0.069ms        event:sql/plan_opt.go:389 [n1,client=127.0.0.1:46960,user=root] query cache add
             4.054ms      4.054ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] planning ends
             4.111ms      0.057ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] checking distributability
             4.162ms      0.050ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] will distribute plan: false
             4.235ms      0.073ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] executing after 0 retries, last retry reason: <nil>
             4.291ms      0.056ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] execution starts: distributed engine
             4.354ms      0.064ms    event:sql/distsql_running.go:1922 [n1,client=127.0.0.1:46960,user=root] creating DistSQL plan with isLocal=true
             4.422ms      0.068ms    event:sql/distsql_running.go:819 [n1,client=127.0.0.1:46960,user=root] running DistSQL plan
             4.467ms      0.045ms        === operation:flow _verbose:1 node:1 client:127.0.0.1:46960 user:root
             4.647ms      0.180ms        event:sql/colflow/vectorized_flow.go:232 [n1,client=127.0.0.1:46960,user=root] setting up vectorized flow
             4.811ms      0.164ms        event:sql/colflow/vectorized_flow.go:282 [n1,client=127.0.0.1:46960,user=root] vectorized flow setup succeeded
             4.873ms      0.062ms        event:sql/flowinfra/flow.go:442 [n1,client=127.0.0.1:46960,user=root] starting (0 processors, 0 startables) asynchronously
             4.924ms      0.051ms        event:sql/colflow/vectorized_flow.go:325 [n1,client=127.0.0.1:46960,user=root] running the batch flow coordinator in the flow's goroutine
            12.459ms      7.535ms        event:component:<flow_id:<7385a3ad-2f74-4920-9a2e-6f82cf5002a7> type:FLOW id:0 sql_instance_id:1 > 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:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_ru:<> >
            12.286ms     -0.172ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"7385a3ad-2f74-4920-9a2e-6f82cf5002a7","type":"FLOW","id":0,"sqlInstanceId":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"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"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"}}}
             4.972ms     -7.314ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:1 client:127.0.0.1:46960 user:root cockroach.flowid:7385a3ad-2f74-4920-9a2e-6f82cf5002a7 cockroach.processorid:0
            11.336ms      6.364ms        event:component:<flow_id:<7385a3ad-2f74-4920-9a2e-6f82cf5002a7> type:PROCESSOR id:0 sql_instance_id:1 > 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:5724270 > > 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:2 > num_internal_seeks:<value_plus_one:2 > block_bytes:<value_plus_one:3787 > block_bytes_in_cache:<value_plus_one:3787 > key_bytes:<value_plus_one:15 > value_bytes:<value_plus_one:15 > point_count:<value_plus_one:2 > points_covered_by_range_tombstones:<value_plus_one:1 > range_key_count:<value_plus_one:1 > range_key_contained_points:<value_plus_one:1 > range_key_skipped_points:<value_plus_one:1 > kv_cpu_time:<> num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_ru:<value_plus_one:1 > cpu_time:<value_plus_one:<nanos:459268 > > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            11.597ms      0.261ms        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:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
            11.135ms     -0.461ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"7385a3ad-2f74-4920-9a2e-6f82cf5002a7","type":"PROCESSOR","id":0,"sqlInstanceId":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":"12"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.005724270s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"3787"},"blockBytesInCache":{"valuePlusOne":"3787"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"15"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000459268s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
            11.392ms      0.257ms        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"},"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"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"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"}}}
             5.100ms     -6.292ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:1 client:127.0.0.1:46960 user:root
             5.100ms      0.000ms        [txn coordinator send: {count: 1, duration 5ms}]
             5.100ms      0.000ms        [dist sender send: {count: 1, duration 4ms}]
             5.100ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             5.547ms      0.447ms        event:sql/row/kv_batch_fetcher.go:475 [n1,client=127.0.0.1:46960,user=root] Scan /Table/108/1/1/0
             5.629ms      0.081ms            === operation:txn coordinator send _verbose:1 node:1 client:127.0.0.1:46960 user:root txnID:a8f00682-00a1-4053-bcff-edec6f0c9546
             5.629ms      0.000ms            [dist sender send: {count: 1, duration 4ms}]
             5.629ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             5.781ms      0.152ms                === operation:dist sender send _verbose:1 node:1 client:127.0.0.1:46960 user:root txn:a8f00682
             5.781ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 1, duration 3ms}]
             5.941ms      0.160ms                event:kv/kvclient/kvcoord/range_iter.go:188 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] querying next range at /Table/108/1/1/0
             6.147ms      0.205ms                event:kv/kvclient/kvcoord/range_iter.go:225 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] key: /Table/108/1/1/0, desc: r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25]
             6.285ms      0.139ms                event:kv/kvclient/kvcoord/dist_sender.go:2051 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] routing to nearest replica; leaseholder not required
             6.887ms      0.602ms                event:kv/kvclient/kvcoord/dist_sender.go:2109 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] r63: sending batch 1 Get to (n1,s1):1
             6.968ms      0.081ms                event:rpc/nodedialer/nodedialer.go:157 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] sending request to local client
             7.030ms      0.061ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: a8f00682], [can-forward-ts]
             7.189ms      0.159ms                    event:server/node.go:1171 [n1] node received request: 1 Get
             7.394ms      0.205ms                    event:kv/kvserver/store_send.go:167 [n1,s1] executing Get [/Table/108/1/1/0,/Min), [txn: a8f00682], [can-forward-ts]
             7.573ms      0.179ms                    event:kv/kvserver/replica_send.go:179 [n1,s1,r63/1:/{Table/108-Max}] read-only path
             7.691ms      0.119ms                    event:kv/kvserver/concurrency/concurrency_manager.go:194 [n1,s1,r63/1:/{Table/108-Max}] sequencing request
             7.749ms      0.058ms                    event:kv/kvserver/concurrency/concurrency_manager.go:275 [n1,s1,r63/1:/{Table/108-Max}] acquiring latches
             7.838ms      0.089ms                    event:kv/kvserver/concurrency/concurrency_manager.go:319 [n1,s1,r63/1:/{Table/108-Max}] scanning lock table for conflicting locks
             8.109ms      0.270ms                    event:kv/kvserver/replica_follower_read.go:127 [n1,s1,r63/1:/{Table/108-Max}] serving via follower read; query timestamp below closed timestamp by 141.121822ms
             8.292ms      0.183ms                    event:kv/kvserver/replica_read.go:296 [n1,s1,r63/1:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: a8f00682], [can-forward-ts]); scanning lock table first to detect conflicts
             8.432ms      0.140ms                    event:kv/kvserver/replica_read.go:113 [n1,s1,r63/1:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
             8.562ms      0.130ms                    event:kv/kvserver/replica_read.go:408 [n1,s1,r63/1:/{Table/108-Max}] executing read-only batch
             8.957ms      0.395ms                    event:kv/kvserver/replica_evaluate.go:550 [n1,s1,r63/1:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=a8f00682 key=/Min pri=0.00520204 epo=0 ts=1681452512.813048908,0 min=1681452512.813048908,0 seq=0} lock=false stat=PENDING rts=1681452512.813048908,0 wto=false gul=1681452513.313048908,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1681452499775152626 > > , err=<nil>
             9.078ms      0.121ms                    event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 3.7 KiB, cached 3.7 KiB); points: (count 1 , key-bytes 14 B, value-bytes 14 B, tombstoned: 0 ) ranges: (count 0 ), (contained-points 0 , skipped-points 0 ) evaluated requests: 1 gets, 0 scans, 0 reverse scans
             9.257ms      0.179ms                    event:kv/kvserver/replica_read.go:221 [n1,s1,r63/1:/{Table/108-Max}] read completed
             9.325ms      0.068ms                    event:kv/kvserver/replica_send.go:321 [n1,s1,r63/1:/{Table/108-Max}] client had stale range info; returning an update
             8.993ms     -0.332ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"3786","blockBytesInCache":"3786","keyBytes":"14","valueBytes":"14","pointCount":"1","pointsCoveredByRangeTombstones":"0","rangeKeyCount":"0","rangeKeyContainedPoints":"0","rangeKeySkippedPoints":"0","separatedPointCount":"0","separatedPointValueBytes":"0","separatedPointValueBytesFetched":"0","numGets":"1","numScans":"0","numReverseScans":"0"}
             9.818ms      2.849ms                event:kv/kvclient/kvcoord/dist_sender.go:2238 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] received updated range info: [desc: r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25], lease: repl=(n2,s2):5 seq=3 start=1681452512.683300499,0 epo=1 pro=1681452512.706779630,0, closed_timestamp_policy: LEAD_FOR_GLOBAL_READS]
             9.990ms      0.172ms                event:kv/kvclient/rangecache/range_cache.go:1083 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] evict cached descriptor: desc=desc:r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25], lease:repl=(n2,s2):5 seq=2 start=1681452512.683300499,0 exp=1681452518.681706531,0 pro=1681452512.681706531,0
            10.046ms      0.056ms                event:kv/kvclient/rangecache/range_cache.go:594 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] evicting cached range descriptor with 1 replacements
            10.123ms      0.077ms                event:kv/kvclient/rangecache/range_cache.go:1252 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] clearing entries overlapping r63:/{Table/108-Max} [(n1,s1):1, (n2,s2):5, (n3,s3):9, (n4,s4):6NON_VOTER, (n5,s5):10NON_VOTER, next=11, gen=25]
            10.408ms      4.779ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n1,client=127.0.0.1:46960,user=root,txn=a8f00682] recording span to refresh: /Table/108/1/1/0
            12.773ms      8.352ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] execution ends
            12.824ms      0.050ms    event:sql/conn_executor_exec.go:963 [n1,client=127.0.0.1:46960,user=root] rows affected: 1
            14.269ms      1.445ms        === operation:commit sql txn _verbose:1 node:1 client:127.0.0.1:46960 user:root
            14.697ms      1.873ms    event:sql/conn_executor_exec.go:2724 [n1,client=127.0.0.1:46960,user=root] AutoCommit. err: <nil>

@chengxiong-ruan
Copy link
Contributor

There is not actual output string from the test failure. So I'm not sure...
I'll try to change the output a little and stress it to see if I can repro.
But the expected output is that the data should be served locally since it's a global table, and it shouldn't be a follower read since server-0 is the leaseholder.

@chengxiong-ruan
Copy link
Contributor

I was not able to repro the exact error on querying server-0, but managed to stress a failure on querying server-4.
Modified the test assertion output a little bit and found that it was supposed to be a local read on server-4, but the read was directed to server-0 for some reason. I don't know why yet. But given that it's a global table that shouldn't happen.

I230418 20:59:31.599364 1 (gostd) rand.go:243  [-] 1  random seed: 693665268076270442
test logs left over in: /tmp/cockroach/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven3256943175
--- FAIL: TestMultiRegionDataDriven (41.58s)
    test_log_scope.go:161: test logs captured to: /tmp/cockroach/_tmp/e558fc8050776f4c54ea39ba371b49da/logTestMultiRegionDataDriven3256943175
    test_log_scope.go:79: use -show-logs to present logs inline
    --- FAIL: TestMultiRegionDataDriven/global_tables (41.53s)
        datadriven_test.go:132:
            /home/cruan/.cache/bazel/_bazel_cruan/284c424e9408a2cd7b6c16049aca8bca/sandbox/linux-sandbox/3722/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/global_tables:68:
             SELECT * FROM db.global WHERE k = 1
            expected:
            served locally: true
            served via follower read: true

            found:
            not a match, actual:
            served locally: false
            , trace:
                 0.000ms      0.000ms    === operation:traced statement _verbose:1 node:5 client:127.0.0.1:44064 user:root
                 0.000ms      0.000ms    [flow: {count: 1, duration 2ms}]
                 0.000ms      0.000ms    [colbatchscan: {count: 1, duration 1ms}]
                 0.000ms      0.000ms    [batch flow coordinator: {count: 1, duration 1ms}]
                 0.000ms      0.000ms    [/cockroach.roachpb.Internal/Batch: {count: 2, duration 1ms}]
                 0.000ms      0.000ms    [txn coordinator send: {count: 1, duration 1ms}]
                 0.000ms      0.000ms    [dist sender send: {count: 1, duration 1ms}]
                 0.000ms      0.000ms    [optimizer: {count: 1, duration 533µs}]
                 0.000ms      0.000ms    [commit sql txn: {count: 1, duration 12µs}]
                 0.008ms      0.008ms        === operation:optimizer _verbose:1 node:5 client:127.0.0.1:44064 user:root
                 0.041ms      0.032ms        event:sql/plan_opt.go:389 [n5,client=127.0.0.1:44064,user=root] query cache miss
                 0.054ms      0.014ms        event:sql/opt/optbuilder/builder.go:201 [n5,client=127.0.0.1:44064,user=root] optbuilder start
                 0.093ms      0.038ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n5,client=127.0.0.1:44064,user=root] descriptorVersionState.incRefCount: 100("defaultdb") ver=1:1681851899.080552619,0, refcount=1
                 0.113ms      0.020ms        event:sql/catalog/descs/descriptor.go:137 [n5,client=127.0.0.1:44064,user=root] looking up descriptors for ids [100]
                 0.136ms      0.023ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n5,client=127.0.0.1:44064,user=root] descriptorVersionState.incRefCount: 104("db") ver=1:1681851926.995387065,0, refcount=1
                 0.149ms      0.013ms        event:sql/catalog/descs/descriptor.go:137 [n5,client=127.0.0.1:44064,user=root] looking up descriptors for ids [104]
                 0.165ms      0.016ms        event:sql/catalog/descs/descriptor.go:137 [n5,client=127.0.0.1:44064,user=root] looking up descriptors for ids [105]
                 0.183ms      0.018ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n5,client=127.0.0.1:44064,user=root] descriptorVersionState.incRefCount: 105("public") ver=1:1681851909.323573731,0, refcount=1
                 0.205ms      0.021ms        event:sql/catalog/lease/descriptor_version_state.go:124 [n5,client=127.0.0.1:44064,user=root] descriptorVersionState.incRefCount: 108("global") ver=1:1681851898.876216225,0, refcount=1
                 0.220ms      0.015ms        event:sql/catalog/descs/descriptor.go:137 [n5,client=127.0.0.1:44064,user=root] looking up descriptors for ids [108]
                 0.411ms      0.191ms        event:sql/opt/optbuilder/builder.go:247 [n5,client=127.0.0.1:44064,user=root] optbuilder finish
                 0.423ms      0.012ms        event:sql/opt/xform/optimizer.go:240 [n5,client=127.0.0.1:44064,user=root] optimize start
                 0.485ms      0.062ms        event:sql/opt/xform/optimizer.go:289 [n5,client=127.0.0.1:44064,user=root] optimize finish
                 0.496ms      0.011ms        event:sql/plan_opt.go:389 [n5,client=127.0.0.1:44064,user=root] query cache add
                 0.571ms      0.571ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] planning ends
                 0.591ms      0.020ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] checking distributability
                 0.607ms      0.016ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] will distribute plan: false
                 0.625ms      0.018ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] executing after 0 retries, last retry reason: <nil>
                 0.642ms      0.018ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] execution starts: distributed engine
                 0.665ms      0.023ms    event:sql/distsql_running.go:1922 [n5,client=127.0.0.1:44064,user=root] creating DistSQL plan with isLocal=true
                 0.690ms      0.025ms    event:sql/distsql_running.go:819 [n5,client=127.0.0.1:44064,user=root] running DistSQL plan
                 0.696ms      0.006ms        === operation:flow _verbose:1 node:5 client:127.0.0.1:44064 user:root
                 0.725ms      0.029ms        event:sql/colflow/vectorized_flow.go:232 [n5,client=127.0.0.1:44064,user=root] setting up vectorized flow
                 0.773ms      0.048ms        event:sql/colflow/vectorized_flow.go:282 [n5,client=127.0.0.1:44064,user=root] vectorized flow setup succeeded
                 0.790ms      0.018ms        event:sql/flowinfra/flow.go:442 [n5,client=127.0.0.1:44064,user=root] starting (0 processors, 0 startables) asynchronously
                 0.802ms      0.011ms        event:sql/colflow/vectorized_flow.go:325 [n5,client=127.0.0.1:44064,user=root] running the batch flow coordinator in the flow's goroutine
                 2.393ms      1.592ms        event:component:<flow_id:<6ac9e186-2a53-471b-8283-37518b0e2f4f> 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:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<value_plus_one:20481 > max_disk_usage:<value_plus_one:1 > consumed_ru:<> >
                 2.305ms     -0.088ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"6ac9e186-2a53-471b-8283-37518b0e2f4f","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"},"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"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"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"}}}
                 0.803ms     -1.502ms        === operation:batch flow coordinator _unfinished:1 _verbose:1 node:5 client:127.0.0.1:44064 user:root cockroach.flowid:6ac9e186-2a53-471b-8283-37518b0e2f4f cockroach.processorid:0
                 2.164ms      1.361ms        event:component:<flow_id:<6ac9e186-2a53-471b-8283-37518b0e2f4f> 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:1185051 > > 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:2 > num_internal_seeks:<value_plus_one:2 > block_bytes:<value_plus_one:90 > block_bytes_in_cache:<value_plus_one:90 > key_bytes:<value_plus_one:15 > value_bytes:<value_plus_one:8 > point_count:<value_plus_one:2 > points_covered_by_range_tombstones:<value_plus_one:1 > range_key_count:<value_plus_one:1 > range_key_contained_points:<value_plus_one:1 > range_key_skipped_points:<value_plus_one:1 > kv_cpu_time:<> num_gets:<value_plus_one:2 > num_scans:<value_plus_one:1 > num_reverse_scans:<value_plus_one:1 > > exec:<exec_time:<> max_allocated_mem:<value_plus_one:20481 > max_allocated_disk:<> consumed_ru:<value_plus_one:1 > cpu_time:<value_plus_one:<nanos:25657 > > > output:<num_batches:<value_plus_one:2 > num_tuples:<value_plus_one:2 > > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
                 2.238ms      0.074ms        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:<> block_bytes:<> block_bytes_in_cache:<> key_bytes:<> value_bytes:<> point_count:<> points_covered_by_range_tombstones:<> range_key_count:<> range_key_contained_points:<> range_key_skipped_points:<> kv_cpu_time:<> num_gets:<> num_scans:<> num_reverse_scans:<> > exec:<exec_time:<> max_allocated_mem:<> max_allocated_disk:<> consumed_ru:<> cpu_time:<> > output:<num_batches:<> num_tuples:<> > flow_stats:<max_mem_usage:<> max_disk_usage:<> consumed_ru:<> >
                 2.029ms     -0.209ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"6ac9e186-2a53-471b-8283-37518b0e2f4f","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.001185051s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"90"},"blockBytesInCache":{"valuePlusOne":"90"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"8"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{"valuePlusOne":"0s"},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000025657s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"inputs":[],"flowStats":{"maxMemUsage":{"valuePlusOne":"0"},"maxDiskUsage":{"valuePlusOne":"0"},"consumedRu":{"valuePlusOne":"0"}}}
                 2.168ms      0.139ms        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"},"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"},"contentionEvents":[],"kvCpuTime":{"valuePlusOne":"0s"},"numGets":{"valuePlusOne":"0"},"numScans":{"valuePlusOne":"0"},"numReverseScans":{"valuePlusOne":"0"}},"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"}}}
                 0.810ms     -1.358ms        === operation:colbatchscan _unfinished:1 _verbose:1 node:5 client:127.0.0.1:44064 user:root
                 0.810ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 2, duration 1ms}]
                 0.810ms      0.000ms        [txn coordinator send: {count: 1, duration 1ms}]
                 0.810ms      0.000ms        [dist sender send: {count: 1, duration 1ms}]
                 0.855ms      0.045ms        event:sql/row/kv_batch_fetcher.go:475 [n5,client=127.0.0.1:44064,user=root] Scan /Table/108/1/1/0
                 0.859ms      0.004ms            === operation:txn coordinator send _verbose:1 node:5 client:127.0.0.1:44064 user:root txnID:9648fc7b-7eec-49b5-9fb5-6ef25f8d8468
                 0.859ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 2, duration 1ms}]
                 0.859ms      0.000ms            [dist sender send: {count: 1, duration 1ms}]
                 0.868ms      0.009ms                === operation:dist sender send _verbose:1 node:5 client:127.0.0.1:44064 user:root txn:9648fc7b
                 0.868ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 2, duration 1ms}]
                 0.900ms      0.032ms                event:kv/kvclient/kvcoord/range_iter.go:188 [n5,client=127.0.0.1:44064,user=root,txn=9648fc7b] querying next range at /Table/108/1/1/0
                 0.965ms      0.065ms                event:kv/kvclient/kvcoord/range_iter.go:225 [n5,client=127.0.0.1:44064,user=root,txn=9648fc7b] key: /Table/108/1/1/0, desc: r63:/{Table/108-Max} [(n3,s3):1, (n2,s2):5, (n1,s1):9, (n4,s4):8NON_VOTER, next=11, gen=30]
                 0.983ms      0.018ms                event:kv/kvclient/kvcoord/dist_sender.go:2051 [n5,client=127.0.0.1:44064,user=root,txn=9648fc7b] routing to nearest replica; leaseholder not required
                 1.019ms      0.035ms                event:kv/kvclient/kvcoord/dist_sender.go:2109 [n5,client=127.0.0.1:44064,user=root,txn=9648fc7b] r63: sending batch 1 Get to (n1,s1):9
                 1.033ms      0.015ms                event:rpc/nodedialer/nodedialer.go:166 [n5,client=127.0.0.1:44064,user=root,txn=9648fc7b] sending request to 127.0.0.1:41629
                 1.041ms      0.007ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:5 client:127.0.0.1:44064 user:root txn:9648fc7b span.kind:client
                 1.229ms      0.188ms                    === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:Get [/Table/108/1/1/0,/Min), [txn: 9648fc7b], [can-forward-ts]
                 1.250ms      0.021ms                    event:server/node.go:1171 [n1] node received request: 1 Get
                 1.300ms      0.050ms                    event:kv/kvserver/store_send.go:167 [n1,s1] executing Get [/Table/108/1/1/0,/Min), [txn: 9648fc7b], [can-forward-ts]
                 1.321ms      0.020ms                    event:kv/kvserver/replica_send.go:179 [n1,s1,r63/9:/{Table/108-Max}] read-only path
                 1.341ms      0.020ms                    event:kv/kvserver/concurrency/concurrency_manager.go:194 [n1,s1,r63/9:/{Table/108-Max}] sequencing request
                 1.353ms      0.012ms                    event:kv/kvserver/concurrency/concurrency_manager.go:275 [n1,s1,r63/9:/{Table/108-Max}] acquiring latches
                 1.378ms      0.025ms                    event:kv/kvserver/concurrency/concurrency_manager.go:319 [n1,s1,r63/9:/{Table/108-Max}] scanning lock table for conflicting locks
                 1.433ms      0.055ms                    event:kv/kvserver/replica_read.go:296 [n1,s1,r63/9:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0,/Min), [txn: 9648fc7b], [can-forward-ts]); scanning lock table first to detect conflicts
                 1.472ms      0.038ms                    event:kv/kvserver/replica_read.go:113 [n1,s1,r63/9:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
                 1.492ms      0.020ms                    event:kv/kvserver/replica_read.go:408 [n1,s1,r63/9:/{Table/108-Max}] executing read-only batch
                 1.608ms      0.116ms                    event:kv/kvserver/replica_evaluate.go:550 [n1,s1,r63/9:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=9648fc7b key=/Min pri=0.00481964 epo=0 ts=1681851612.933361478,0 min=1681851612.933361478,0 seq=0} lock=false stat=PENDING rts=1681851612.933361478,0 wto=false gul=1681851613.433361478,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1681851595683500144 > > , err=<nil>
                 1.651ms      0.043ms                    event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 89 B, cached 89 B); 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.668ms      0.017ms                    event:kv/kvserver/replica_read.go:221 [n1,s1,r63/9:/{Table/108-Max}] read completed
                 1.613ms     -0.055ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0","blockBytes":"89","blockBytesInCache":"89","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.956ms      1.098ms            event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:576 [n5,client=127.0.0.1:44064,user=root,txn=9648fc7b] recording span to refresh: /Table/108/1/1/0
                 2.440ms      1.750ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] execution ends
                 2.454ms      0.014ms    event:sql/conn_executor_exec.go:963 [n5,client=127.0.0.1:44064,user=root] rows affected: 1
                 2.604ms      0.150ms        === operation:commit sql txn _verbose:1 node:5 client:127.0.0.1:44064 user:root
                 2.651ms      0.197ms    event:sql/conn_executor_exec.go:2724 [n5,client=127.0.0.1:44064,user=root] AutoCommit. err: <nil>
    datadriven_test.go:436: -- test log scope end --
FAIL
I230418 21:00:13.326942 1 (gostd) testmain.go:136  [-] 1  Test //pkg/ccl/multiregionccl:multiregionccl_test exited with error code 1


ERROR: exit status 1

477 runs completed, 1 failures, over 15m34s
context canceled

@cockroach-teamcity cockroach-teamcity mentioned this issue Apr 19, 2023
Closed
@cockroach-teamcity cockroach-teamcity mentioned this issue May 7, 2023
Closed
@exalate-issue-sync exalate-issue-sync bot added T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions) and removed T-sql-schema-deprecated Use T-sql-foundations instead labels May 10, 2023
@cockroach-teamcity cockroach-teamcity mentioned this issue May 16, 2023
Closed
@rafiss rafiss closed this as completed May 30, 2023
@exalate-issue-sync exalate-issue-sync bot reopened this Jun 27, 2023
@chengxiong-ruan
Copy link
Contributor

closing in favor of #98020

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@chengxiong-ruan chengxiong-ruan

Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Projects
None yet
Milestone
23.1
Development

No branches or pull requests
3 participants
@rafiss @chengxiong-ruan @cockroach-teamcity