Giter Club home page Giter Club logo

Comments (2)

rafiss avatar rafiss commented on August 16, 2024 
        /var/lib/engflow/worker/work/1/exec/bazel-out/k8-fastbuild/bin/pkg/ccl/multiregionccl/multiregionccl_test_/multiregionccl_test.runfiles/com_github_cockroachdb_cockroach/pkg/ccl/multiregionccl/testdata/global_tables:98:
         SELECT * FROM db.global WHERE k = 1
        expected:
        served locally: true
        served via follower read: true
        
        found:
        not a match, trace:
             0.000ms      0.000ms    === operation:traced statement _unfinished:1 _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root
             0.000ms      0.000ms    [flow: {count: 1, duration 32ms}]
             0.000ms      0.000ms    [colbatchscan: {count: 1, duration 32ms, unfinished}]
             0.000ms      0.000ms    [batch flow coordinator: {count: 1, duration 32ms}]
             0.000ms      0.000ms    [txn coordinator send: {count: 1, duration 32ms}]
             0.000ms      0.000ms    [dist sender send: {count: 1, duration 32ms}]
             0.000ms      0.000ms    [/cockroach.roachpb.Internal/Batch: {count: 3, duration 32ms}]
             0.000ms      0.000ms    [optimizer: {count: 1, duration 469µs}]
             0.000ms      0.000ms    [commit sql txn: {count: 1, duration 8µs}]
             0.004ms      0.004ms        === operation:optimizer _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root
             0.057ms      0.052ms        event:sql/catalog/lease/descriptor_version_state.go:143 [n6,client=127.0.0.1:45318,hostssl,user=root] descriptorVersionState.incRefCount: 100("defaultdb",0101809a0b436ba55e47939f54b9ad6edebe9b) ver=1:1718525651.258289234,0, refcount=1
             0.075ms      0.018ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [100]
             0.106ms      0.032ms        event:sql/catalog/lease/descriptor_version_state.go:143 [n6,client=127.0.0.1:45318,hostssl,user=root] descriptorVersionState.incRefCount: 104("db",0101809a0b436ba55e47939f54b9ad6edebe9b) ver=1:1718525653.087944979,0, refcount=1
             0.122ms      0.016ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [104]
             0.134ms      0.012ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [105]
             0.153ms      0.018ms        event:sql/catalog/lease/descriptor_version_state.go:143 [n6,client=127.0.0.1:45318,hostssl,user=root] descriptorVersionState.incRefCount: 105("public",0101809a0b436ba55e47939f54b9ad6edebe9b) ver=1:1718525649.667795442,0, refcount=1
             0.175ms      0.022ms        event:sql/catalog/lease/descriptor_version_state.go:143 [n6,client=127.0.0.1:45318,hostssl,user=root] descriptorVersionState.incRefCount: 108("global",0101809a0b436ba55e47939f54b9ad6edebe9b) ver=1:1718525653.650390256,0, refcount=1
             0.187ms      0.012ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [108]
             0.212ms      0.025ms        event:sql/plan_opt.go:406 [n6,client=127.0.0.1:45318,hostssl,user=root] query cache hit but needed update
             0.225ms      0.013ms        event:sql/opt/optbuilder/builder.go:217 [n6,client=127.0.0.1:45318,hostssl,user=root] optbuilder start
             0.245ms      0.020ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [100]
             0.257ms      0.012ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [104]
             0.268ms      0.011ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [105]
             0.279ms      0.011ms        event:sql/catalog/descs/descriptor.go:137 [n6,client=127.0.0.1:45318,hostssl,user=root] looking up descriptors for ids [108]
             0.381ms      0.103ms        event:sql/opt/optbuilder/builder.go:263 [n6,client=127.0.0.1:45318,hostssl,user=root] optbuilder finish
             0.392ms      0.011ms        event:sql/plan_opt.go:406 [n6,client=127.0.0.1:45318,hostssl,user=root] optimizing (no placeholders)
             0.402ms      0.010ms        event:sql/opt/xform/optimizer.go:241 [n6,client=127.0.0.1:45318,hostssl,user=root] optimize start
             0.449ms      0.047ms        event:sql/opt/xform/optimizer.go:290 [n6,client=127.0.0.1:45318,hostssl,user=root] optimize finish
             0.507ms      0.507ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] planning ends
             0.521ms      0.014ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] checking distributability
             0.532ms      0.012ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] will distribute plan: false
             0.548ms      0.015ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] executing after 0 retries, last retry reason: <nil>
             0.562ms      0.014ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] execution starts: distributed engine
             0.579ms      0.018ms    event:sql/distsql_running.go:1979 [n6,client=127.0.0.1:45318,hostssl,user=root] creating DistSQL plan with isLocal=true
             0.596ms      0.017ms    event:sql/distsql_running.go:835 [n6,client=127.0.0.1:45318,hostssl,user=root] running DistSQL plan
             0.599ms      0.003ms        === operation:flow _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root
             0.599ms      0.000ms        [colbatchscan: {count: 1, duration 32ms, unfinished}]
             0.599ms      0.000ms        [batch flow coordinator: {count: 1, duration 32ms}]
             0.599ms      0.000ms        [txn coordinator send: {count: 1, duration 32ms}]
             0.599ms      0.000ms        [dist sender send: {count: 1, duration 32ms}]
             0.599ms      0.000ms        [/cockroach.roachpb.Internal/Batch: {count: 3, duration 32ms}]
             0.620ms      0.021ms        event:sql/colflow/vectorized_flow.go:231 [n6,client=127.0.0.1:45318,hostssl,user=root] setting up vectorized flow
             0.647ms      0.027ms        event:sql/colflow/vectorized_flow.go:272 [n6,client=127.0.0.1:45318,hostssl,user=root] vectorized flow setup succeeded
             0.662ms      0.015ms        event:sql/flowinfra/flow.go:465 [n6,client=127.0.0.1:45318,hostssl,user=root] starting (0 processors, 0 startables) asynchronously
             0.675ms      0.013ms        event:sql/colflow/vectorized_flow.go:319 [n6,client=127.0.0.1:45318,hostssl,user=root] running the batch flow coordinator in the flow's goroutine
             0.676ms      0.001ms            === operation:batch flow coordinator _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root cockroach.flowid:c59791a5-c47c-4720-a5df-e996d231074d cockroach.processorid:0
             0.676ms      0.000ms            [colbatchscan: {count: 1, duration 32ms, unfinished}]
             0.676ms      0.000ms            [txn coordinator send: {count: 1, duration 32ms}]
             0.676ms      0.000ms            [dist sender send: {count: 1, duration 32ms}]
             0.676ms      0.000ms            [/cockroach.roachpb.Internal/Batch: {count: 3, duration 32ms}]
             0.679ms      0.004ms                === operation:colbatchscan _unfinished:1 _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root cockroach.flowid:c59791a5-c47c-4720-a5df-e996d231074d cockroach.processorid:0
             0.679ms      0.000ms                [txn coordinator send: {count: 1, duration 32ms}]
             0.679ms      0.000ms                [dist sender send: {count: 1, duration 32ms}]
             0.679ms      0.000ms                [/cockroach.roachpb.Internal/Batch: {count: 3, duration 32ms}]
             0.710ms      0.031ms                event:sql/row/kv_batch_fetcher.go:535 [n6,client=127.0.0.1:45318,hostssl,user=root] Scan /Table/108/1/1/0
             0.713ms      0.003ms                    === operation:txn coordinator send _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root txnID:d8b3fd67-0174-46f7-91f8-fde2964dea81
             0.713ms      0.000ms                    [dist sender send: {count: 1, duration 32ms}]
             0.713ms      0.000ms                    [/cockroach.roachpb.Internal/Batch: {count: 3, duration 32ms}]
             0.722ms      0.009ms                        === operation:dist sender send _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root txn:d8b3fd67
             0.722ms      0.000ms                        [/cockroach.roachpb.Internal/Batch: {count: 3, duration 32ms}]
             0.747ms      0.025ms                        event:kv/kvclient/kvcoord/range_iter.go:188 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] querying next range at /Table/108/1/1/0
             0.798ms      0.051ms                        event:kv/kvclient/kvcoord/range_iter.go:225 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] key: /Table/108/1/1/0, desc: r69:/{Table/108-Max} [(n1,s1):1, (n3,s3):8, (n2,s2):5, (n4,s4):6NON_VOTER, (n5,s5):9NON_VOTER, (n6,s6):10NON_VOTER, next=11, gen=24]
             0.818ms      0.020ms                        event:kv/kvclient/kvcoord/dist_sender.go:2574 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] routing to nearest replica; leaseholder not required
             0.851ms      0.033ms                        event:kv/kvclient/kvcoord/dist_sender.go:2637 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] r69: sending batch 1 Get to (n6,s6):10NON_VOTER
             0.869ms      0.018ms                        event:rpc/nodedialer/nodedialer.go:138 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] sending request to local client
             0.881ms      0.012ms                        event:kv/kvclient/kvcoord/transport.go:213 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] sending batch request
             0.886ms      0.006ms                            === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:6 span.kind:server request:Get [/Table/108/1/1/0], [txn: d8b3fd67], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 10485760]
             0.897ms      0.011ms                            event:server/node.go:1402 [n6] node received request: 1 Get
             0.926ms      0.029ms                            event:kv/kvserver/store_send.go:154 [n6,s6] executing Get [/Table/108/1/1/0], [txn: d8b3fd67], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 10485760]
             0.940ms      0.013ms                            event:kv/kvserver/replica_send.go:180 [n6,s6,r69/10:/{Table/108-Max}] read-only path
             0.954ms      0.014ms                            event:kv/kvserver/concurrency/concurrency_manager.go:214 [n6,s6,r69/10:/{Table/108-Max}] sequencing request
             0.964ms      0.010ms                            event:kv/kvserver/concurrency/concurrency_manager.go:295 [n6,s6,r69/10:/{Table/108-Max}] acquiring latches
             0.977ms      0.013ms                            event:kv/kvserver/concurrency/concurrency_manager.go:339 [n6,s6,r69/10:/{Table/108-Max}] scanning lock table for conflicting locks
             1.004ms      0.027ms                            event:kv/kvserver/replica_follower_read.go:118 [n6,s6,r69/10:/{Table/108-Max}] can't serve follower read; closed timestamp too low by: 10.917896ms; maxClosed: 1718525371.426935236,0 ts: 1718525370.937853132,0 uncertaintyLimit: 1718525371.437853132,0
             1.096ms      0.092ms                            event:kv/kvserver/replica_send.go:199 [n6,s6,r69/10:/{Table/108-Max}] replica.Send got error: [NotLeaseHolderError] lease held by different store; r69: replica (n6,s6):10NON_VOTER not lease holder; current lease is repl=(n1,s1):1 seq=1 start=0,0 exp=1718525376.751746571,0 pro=1718525370.751746571,0
             1.158ms      0.062ms                            event:server/node.go:1459 [n6] error from stores.Send: [NotLeaseHolderError] lease held by different store; r69: replica (n6,s6):10NON_VOTER not lease holder; current lease is repl=(n1,s1):1 seq=1 start=0,0 exp=1718525376.751746571,0 pro=1718525370.751746571,0: "sql txn" meta={id=d8b3fd67 key=/Min iso=Serializable pri=0.03309757 epo=0 ts=1718525370.937853132,0 min=1718525370.937853132,0 seq=0} lock=false stat=PENDING rts=1718525370.937853132,0 wto=false gul=1718525371.437853132,0
             1.173ms      0.014ms                            event:server/node.go:1496 [n6] node sending response
             1.215ms      0.335ms                        event:kv/kvclient/kvcoord/transport.go:215 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] received batch response
             1.275ms      0.060ms                        event:kv/kvclient/kvcoord/dist_sender.go:2866 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] [NotLeaseHolderError] lease held by different store; r69: replica (n6,s6):10NON_VOTER not lease holder; current lease is repl=(n1,s1):1 seq=1 start=0,0 exp=1718525376.751746571,0 pro=1718525370.751746571,0: "sql txn" meta={id=d8b3fd67 key=/Min iso=Serializable pri=0.03309757 epo=0 ts=1718525370.937853132,0 min=1718525370.937853132,0 seq=0} lock=false stat=PENDING rts=1718525370.937853132,0 wto=false gul=1718525371.437853132,0
             1.332ms      0.057ms                        event:kv/kvclient/kvcoord/dist_sender.go:3115 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] application error: [NotLeaseHolderError] lease held by different store; r69: replica (n6,s6):10NON_VOTER not lease holder; current lease is repl=(n1,s1):1 seq=1 start=0,0 exp=1718525376.751746571,0 pro=1718525370.751746571,0: "sql txn" meta={id=d8b3fd67 key=/Min iso=Serializable pri=0.03309757 epo=0 ts=1718525370.937853132,0 min=1718525370.937853132,0 seq=0} lock=false stat=PENDING rts=1718525370.937853132,0 wto=false gul=1718525371.437853132,0
             1.356ms      0.024ms                        event:kv/kvclient/kvcoord/dist_sender.go:2640 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] trying next peer (n1,s1):1
             1.374ms      0.018ms                        event:rpc/nodedialer/nodedialer.go:147 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] sending request to 127.0.0.1:40611
             1.391ms      0.017ms                        event:kv/kvclient/kvcoord/transport.go:213 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] sending batch request
             1.393ms      0.002ms                            === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root txn:d8b3fd67 span.kind:client
            11.089ms      9.696ms                            === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:Get [/Table/108/1/1/0], [txn: d8b3fd67], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 10485760]
            11.113ms      0.024ms                            event:server/node.go:1402 [n1] node received request: 1 Get
            11.147ms      0.034ms                            event:kv/kvserver/store_send.go:154 [n1,s1] executing Get [/Table/108/1/1/0], [txn: d8b3fd67], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 10485760]
            11.161ms      0.014ms                            event:kv/kvserver/replica_send.go:180 [n1,s1,r69/1:/{Table/108-Max}] read-only path
            11.178ms      0.017ms                            event:kv/kvserver/concurrency/concurrency_manager.go:214 [n1,s1,r69/1:/{Table/108-Max}] sequencing request
            11.188ms      0.010ms                            event:kv/kvserver/concurrency/concurrency_manager.go:295 [n1,s1,r69/1:/{Table/108-Max}] acquiring latches
            11.201ms      0.013ms                            event:kv/kvserver/concurrency/concurrency_manager.go:339 [n1,s1,r69/1:/{Table/108-Max}] scanning lock table for conflicting locks
            11.240ms      0.039ms                            event:kv/kvserver/replica_read.go:312 [n1,s1,r69/1:/{Table/108-Max}] can drop latches early for batch (Get [/Table/108/1/1/0], [txn: d8b3fd67], [can-forward-ts], [max_span_request_keys: 0], [target_bytes: 10485760]); scanning lock table first to detect conflicts
            11.272ms      0.032ms                            event:kv/kvserver/replica_read.go:124 [n1,s1,r69/1:/{Table/108-Max}] lock table scan complete without conflicts; dropping latches early
            11.289ms      0.017ms                            event:kv/kvserver/replica_read.go:425 [n1,s1,r69/1:/{Table/108-Max}] executing read-only batch
            11.378ms      0.089ms                            event:kv/kvserver/replica_evaluate.go:512 [n1,s1,r69/1:/{Table/108-Max}] evaluated Get command header:<key:"\364\211\211\210" > , txn="sql txn" meta={id=d8b3fd67 key=/Min iso=Serializable pri=0.03309757 epo=0 ts=1718525370.937853132,0 min=1718525370.937853132,0 seq=0} lock=false stat=PENDING rts=1718525370.937853132,0 wto=false gul=1718525371.437853132,0 : resp=header:<num_keys:1 num_bytes:7 > value:<raw_bytes:"\375\311[\010\n#\002" timestamp:<wall_time:1718525345291038681 > > , err=<nil>
            11.406ms      0.028ms                            event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal); block-bytes: (total 7.5 KiB, cached 7.5 KiB, duration 0s); 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 separated: (count: 2, bytes: 78 B, bytes-fetched: 0 B)
            11.421ms      0.015ms                            event:kv/kvserver/replica_read.go:237 [n1,s1,r69/1:/{Table/108-Max}] read completed
            11.452ms      0.031ms                            event:server/node.go:1496 [n1] node sending response
            11.382ms     -0.070ms                            structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","blockBytes":"7714","blockBytesInCache":"7714","keyBytes":"14","valueBytes":"14","pointCount":"1","separatedPointCount":"2","separatedPointValueBytes":"78","numGets":"1"}
            32.889ms     31.498ms                        event:kv/kvclient/kvcoord/transport.go:215 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] received batch response
            32.947ms     32.235ms                    event:kv/kvclient/kvcoord/txn_interceptor_span_refresher.go:661 [n6,client=127.0.0.1:45318,hostssl,user=root,txn=d8b3fd67] recording span to refresh: /Table/108/1/1/0
            33.024ms     32.348ms            event:ComponentStats{ID: {c59791a5-c47c-4720-a5df-e996d231074d PROCESSOR 0 6 }, KV time: 32ms, KV contention time: 0µs, KV rows decoded: 1, KV bytes read: 11 B, KV gRPC calls: 1, KV pairs read: 1, MVCC step count (ext/int): 0/0, MVCC seek count (ext/int): 1/1, max memory allocated: 20 KiB, sql cpu time: 19µs, batches output: 1, rows output: 1}
            33.029ms      0.005ms            event:ComponentStats{ID: {00000000-0000-0000-0000-000000000000 UNSET 0 ? }}
            32.992ms     -0.037ms            structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"c59791a5-c47c-4720-a5df-e996d231074d","type":"PROCESSOR","sqlInstanceId":6},"netRx":{"latency":{},"waitTime":{},"deserializationTime":{},"tuplesReceived":{},"bytesReceived":{},"messagesReceived":{}},"netTx":{"tuplesSent":{},"bytesSent":{},"messagesSent":{}},"kv":{"bytesRead":{"valuePlusOne":"12"},"kvPairsRead":{"valuePlusOne":"2"},"tuplesRead":{"valuePlusOne":"2"},"batchRequestsIssued":{"valuePlusOne":"2"},"kvTime":{"valuePlusOne":"0.032301829s"},"contentionTime":{"valuePlusOne":"0.000000001s"},"numInterfaceSteps":{"valuePlusOne":"1"},"numInternalSteps":{"valuePlusOne":"1"},"numInterfaceSeeks":{"valuePlusOne":"2"},"numInternalSeeks":{"valuePlusOne":"2"},"blockBytes":{"valuePlusOne":"7715"},"blockBytesInCache":{"valuePlusOne":"7715"},"keyBytes":{"valuePlusOne":"15"},"valueBytes":{"valuePlusOne":"15"},"pointCount":{"valuePlusOne":"2"},"pointsCoveredByRangeTombstones":{"valuePlusOne":"1"},"rangeKeyCount":{"valuePlusOne":"1"},"rangeKeyContainedPoints":{"valuePlusOne":"1"},"rangeKeySkippedPoints":{"valuePlusOne":"1"},"kvCpuTime":{},"numGets":{"valuePlusOne":"2"},"numScans":{"valuePlusOne":"1"},"numReverseScans":{"valuePlusOne":"1"}},"exec":{"execTime":{},"maxAllocatedMem":{"valuePlusOne":"20481"},"maxAllocatedDisk":{},"consumedRu":{"valuePlusOne":"1"},"cpuTime":{"valuePlusOne":"0.000018511s"}},"output":{"numBatches":{"valuePlusOne":"2"},"numTuples":{"valuePlusOne":"2"}},"flowStats":{"maxMemUsage":{},"maxDiskUsage":{},"consumedRu":{}}}
            33.026ms      0.034ms            structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"00000000-0000-0000-0000-000000000000"},"netRx":{"latency":{},"waitTime":{},"deserializationTime":{},"tuplesReceived":{},"bytesReceived":{},"messagesReceived":{}},"netTx":{"tuplesSent":{},"bytesSent":{},"messagesSent":{}},"kv":{"bytesRead":{},"kvPairsRead":{},"tuplesRead":{},"batchRequestsIssued":{},"kvTime":{},"contentionTime":{},"numInterfaceSteps":{},"numInternalSteps":{},"numInterfaceSeeks":{},"numInternalSeeks":{},"blockBytes":{},"blockBytesInCache":{},"keyBytes":{},"valueBytes":{},"pointCount":{},"pointsCoveredByRangeTombstones":{},"rangeKeyCount":{},"rangeKeyContainedPoints":{},"rangeKeySkippedPoints":{},"kvCpuTime":{},"numGets":{},"numScans":{},"numReverseScans":{}},"exec":{"execTime":{},"maxAllocatedMem":{},"maxAllocatedDisk":{},"consumedRu":{},"cpuTime":{}},"output":{"numBatches":{},"numTuples":{}},"flowStats":{"maxMemUsage":{},"maxDiskUsage":{},"consumedRu":{}}}
            33.059ms     32.384ms        event:ComponentStats{ID: {c59791a5-c47c-4720-a5df-e996d231074d FLOW 0 6 eu-central-1}}
            33.056ms     -0.004ms        structured:{"@type":"type.googleapis.com/cockroach.sql.distsqlrun.ComponentStats","component":{"flowId":"c59791a5-c47c-4720-a5df-e996d231074d","type":"FLOW","sqlInstanceId":6,"region":"eu-central-1"},"netRx":{"latency":{},"waitTime":{},"deserializationTime":{},"tuplesReceived":{},"bytesReceived":{},"messagesReceived":{}},"netTx":{"tuplesSent":{},"bytesSent":{},"messagesSent":{}},"kv":{"bytesRead":{},"kvPairsRead":{},"tuplesRead":{},"batchRequestsIssued":{},"kvTime":{},"contentionTime":{},"numInterfaceSteps":{},"numInternalSteps":{},"numInterfaceSeeks":{},"numInternalSeeks":{},"blockBytes":{},"blockBytesInCache":{},"keyBytes":{},"valueBytes":{},"pointCount":{},"pointsCoveredByRangeTombstones":{},"rangeKeyCount":{},"rangeKeyContainedPoints":{},"rangeKeySkippedPoints":{},"kvCpuTime":{},"numGets":{},"numScans":{},"numReverseScans":{}},"exec":{"execTime":{},"maxAllocatedMem":{},"maxAllocatedDisk":{},"consumedRu":{},"cpuTime":{}},"output":{"numBatches":{},"numTuples":{}},"flowStats":{"maxMemUsage":{"valuePlusOne":"20481"},"maxDiskUsage":{"valuePlusOne":"1"},"consumedRu":{}}}
            33.124ms     32.528ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] execution ends
            33.138ms      0.014ms    event:sql/conn_executor_exec.go:1150 [n6,client=127.0.0.1:45318,hostssl,user=root] rows affected: 1
            33.201ms      0.063ms        === operation:commit sql txn _verbose:1 node:6 client:127.0.0.1:45318 hostssl: user:root
            33.240ms      0.101ms    event:sql/conn_executor_exec.go:3151 [n6,client=127.0.0.1:45318,hostssl,user=root] AutoCommit. err: <nil>

The relevant part of the the trace is here, which says a follower read couldn't be used since the closed timestamp was too low:

             1.004ms      0.027ms                            event:kv/kvserver/replica_follower_read.go:118 [n6,s6,r69/10:/{Table/108-Max}] can't serve follower read; closed timestamp too low by: 10.917896ms; maxClosed: 1718525371.426935236,0 ts: 1718525370.937853132,0 uncertaintyLimit: 1718525371.437853132,0
             1.096ms      0.092ms                            event:kv/kvserver/replica_send.go:199 [n6,s6,r69/10:/{Table/108-Max}] replica.Send got error: [NotLeaseHolderError] lease held by different store; r69: replica (n6,s6):10NON_VOTER not lease holder; current lease is repl=(n1,s1):1 seq=1 start=0,0 exp=1718525376.751746571,0 pro=1718525370.751746571,0
             1.158ms      0.062ms                            event:server/node.go:1459 [n6] error from stores.Send: [NotLeaseHolderError] lease held by different store; r69: replica (n6,s6):10NON_VOTER not lease holder; current lease is repl=(n1,s1):1 seq=1 start=0,0 exp=1718525376.751746571,0 pro=1718525370.751746571,0: "sql txn" meta={id=d8b3fd67 key=/Min iso=Serializable pri=0.03309757 epo=0 ts=1718525370.937853132,0 min=1718525370.937853132,0 seq=0} lock=false stat=PENDING rts=1718525370.937853132,0 wto=false gul=1718525371.437853132,0
             1.173ms      0.014ms                            event:server/node.go:1496 [n6] node sending response

Right before this, the test verifies that the correct closed timestamp policy is being used.

wait-for-zone-config-changes db-name=db table-name=global num-voters=3 num-non-voters=3 leaseholder=0 non-voter=5
----

refresh-range-descriptor-cache idx=5 table-name=global
SELECT * FROM db.global WHERE k = 2
----
LEAD_FOR_GLOBAL_READS

I dug in a bit further into the KV code where the can't serve follower read message came from.

cockroach/pkg/kv/kvserver/replica_follower_read.go

Lines 106 to 121 in e9a6d3d

requiredFrontier := ba.RequiredFrontier()
maxClosed := r.getCurrentClosedTimestampLocked(ctx, requiredFrontier /* sufficient */)
canServeFollowerRead := requiredFrontier.LessEq(maxClosed)
tsDiff := requiredFrontier.GoTime().Sub(maxClosed.GoTime())
if !canServeFollowerRead {
uncertaintyLimitStr := "n/a"
if ba.Txn != nil {
uncertaintyLimitStr = ba.Txn.GlobalUncertaintyLimit.String()
}
// We can't actually serve the read based on the closed timestamp.
// Signal the clients that we want an update so that future requests can succeed.
log.Eventf(ctx, "can't serve follower read; closed timestamp too low by: %s; maxClosed: %s ts: %s uncertaintyLimit: %s",
tsDiff, maxClosed, ba.Timestamp, uncertaintyLimitStr)
return false
}

I'm not familiar with this code, so I'm not sure how this relates to getGlobalReadsLead. But I do see that the getCurrentClosedTimestampLocked function checks the sideTransportClosedTimestamp. Is that related to the kv.closed_timestamp.side_transport_interval setting, which is modified by this test?

Hoping the KV team can help to track down why we would see the can't serve follower read; closed timestamp too low by: 10.917896ms message.

This previously came up in #124359. In that issue, the kv.closed_timestamp.propagation_slack was discussed, but @kvoli pointed out that this setting is irrelevant for LEAD_FOR_GLOBAL_READS.

from cockroach.

arulajmani avatar arulajmani commented on August 16, 2024

@rafiss this test seems to be failing because the closed timestamp hasn't propagated to the follower so it can't serve the read. Looks like this flaked; we see a fair few side transport connections dropped in the logs:

W240616 08:12:56.044778 462692 kv/kvserver/closedts/sidetransport/receiver.go:140 ⋮ [n9,remote=4] 11687  closed timestamps side-transport connection dropped from node: 4 (grpc: ‹context canceled› [code 1/Canceled])
W240616 08:12:56.044872 456353 kv/kvserver/closedts/sidetransport/receiver.go:140 ⋮ [n2,remote=4] 11688  closed timestamps side-transport connection dropped from node: 4 (grpc: ‹context canceled› [code 1/Canceled])

I'll close this out as an infra flake. In general, if you see such symptoms where the closed timestamp is lagging (esp on EngFlow, where tests seem to run into overload issues), feel free to close them out as infra flakes; they're annoying but benign.

from cockroach.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.