kv/kvserver: TestProtectedTimestamps failed #109244
Description
kv/kvserver.TestProtectedTimestamps failed with artifacts on master @ c040b7338a946157b57ffe4f1207bff2bbd46576:
5.757ms 0.009ms event:kv/kvserver/replica_raft.go:275 [n1,s1,r65/1:/{Table/104-Max}] acquiring proposal quota (172 bytes)
5.770ms 0.013ms event:kv/kvserver/replica_raft.go:431 [n1,s1,r65/1:/{Table/104-Max}] submitting proposal to proposal buffer
5.827ms 0.057ms event:kv/kvserver/replica_proposal_buf.go:601 [n1,s1,r65/1:/{Table/104-Max}] flushing proposal to Raft
5.888ms 0.061ms === operation:local proposal _verbose:1 node:1 store:1 range:65/1:/{Table/104-Max} raft:
5.916ms 0.028ms event:kv/kvserver/app_batch.go:121 [n1,s1,r65/1:/{Table/104-Max},raft] applying command
5.994ms 0.078ms event:kv/kvserver/replica_application_state_machine.go:176 [n1,s1,r65/1:/{Table/104-Max},raft] LocalResult (reply: (err: <nil>), *kvpb.GCResponse, #encountered intents: 0, #acquired locks: 0, #resolved locks: 0#updated txns: 0 #end txns: 0, GossipFirstRange:false MaybeGossipSystemConfig:false MaybeGossipSystemConfigIfHaveFailure:false MaybeAddToSplitQueue:false MaybeGossipNodeLiveness:<nil>
7.842ms 2.015ms event:kv/kvserver/gc/gc.go:379 [n1,s1,r65/1:/{Table/104-Max}] processing AbortSpan
7.895ms 0.053ms event:kv/kvserver/gc/gc.go:387 [n1,s1,r65/1:/{Table/104-Max}] GC'ed keys; stats {Now:1692717349.541737651,0 GCTTL:1s NumKeysAffected:1 NumRangeKeysAffected:0 IntentsConsidered:0 IntentTxns:0 TransactionSpanTotal:0 TransactionSpanGCAborted:0 TransactionSpanGCCommitted:0 TransactionSpanGCStaging:0 TransactionSpanGCPending:0 AbortSpanTotal:0 AbortSpanConsidered:0 AbortSpanGCNum:0 PushTxn:0 ResolveTotal:0 Threshold:1692717348.541737651,0 AffectedVersionsKeyBytes:47396 AffectedVersionsValBytes:91382276 AffectedVersionsRangeKeyBytes:0 AffectedVersionsRangeValBytes:0 ClearRangeSpanOperations:1 ClearRangeSpanFailures:0}
7.931ms 0.036ms event:kv/kvserver/mvcc_gc_queue.go:777 [n1,s1,r65/1:/{Table/104-Max}] MVCC stats after GC: {ContainsEstimates:0 LastUpdateNanos:1692717351413340377 IntentAge:0 GCBytesAge:65053376 LiveBytes:32794 LiveCount:1 KeyBytes:15677 KeyCount:1 ValBytes:42806762 ValCount:1306 IntentBytes:0 IntentCount:0 SeparatedIntentCount:0 RangeKeyCount:0 RangeKeyBytes:0 RangeValCount:0 RangeValBytes:0 SysBytes:285 SysCount:6 AbortSpanBytes:0}
7.952ms 0.021ms event:kv/kvserver/mvcc_gc_queue.go:778 [n1,s1,r65/1:/{Table/104-Max}] GC score after GC: queue=true with 1.46/fuzz(0.96)=1.52=valScaleScore(1.52)*deadFrac(1.00)+intentScore(0.00)
likely last GC: never, 41 MiB non-live, curr. age 62 MiB*s, min exp. reduction: 21 MiB*s
7.963ms 0.011ms event:kv/kvserver/mvcc_gc_queue.go:794 [n1,s1,r65/1:/{Table/104-Max}] GC still needed following GC, recomputing MVCC stats
7.988ms 0.024ms event:kv/kvserver/mvcc_gc_queue.go:795 [n1,s1,r65/1:/{Table/104-Max}] old score queue=true with 2.48/fuzz(0.96)=2.58=valScaleScore(2.58)*deadFrac(1.00)+intentScore(0.00)
likely last GC: never, 128 MiB non-live, curr. age 330 MiB*s, min exp. reduction: 202 MiB*s
8.005ms 0.017ms event:kv/kvserver/mvcc_gc_queue.go:796 [n1,s1,r65/1:/{Table/104-Max}] new score queue=true with 1.46/fuzz(0.96)=1.52=valScaleScore(1.52)*deadFrac(1.00)+intentScore(0.00)
likely last GC: never, 41 MiB non-live, curr. age 62 MiB*s, min exp. reduction: 21 MiB*s
8.013ms 0.009ms === operation:dist sender send _verbose:1 node:1 store:1 range:65/1:/{Table/104-Max}
8.013ms 0.000ms [/cockroach.roachpb.Internal/Batch: {count: 1, duration 1ms}]
8.013ms 0.000ms [local proposal: {count: 1, duration 97µs}]
8.037ms 0.023ms event:kv/kvclient/kvcoord/range_iter.go:188 [n1,s1,r65/1:/{Table/104-Max}] querying next range at /Table/104
8.067ms 0.031ms event:kv/kvclient/kvcoord/range_iter.go:225 [n1,s1,r65/1:/{Table/104-Max}] key: /Table/104, desc: r65:/{Table/104-Max} [(n1,s1):1, next=2, gen=1]
8.085ms 0.018ms event:kv/kvclient/kvcoord/dist_sender.go:2248 [n1,s1,r65/1:/{Table/104-Max}] r65: sending batch 1 RecomputeStats to (n1,s1):1
8.117ms 0.032ms event:kv/kvclient/kvcoord/dist_sender.go:2563 [n1,s1,r65/1:/{Table/104-Max}] unable to determine if the given nodes are cross zone localities must have a valid zone tier key for cross-zone comparison
8.126ms 0.010ms event:rpc/nodedialer/nodedialer.go:138 [n1,s1,r65/1:/{Table/104-Max}] sending request to local client
8.151ms 0.024ms event:server/node.go:1412 [n1] unable to determine if the given nodes are cross zone localities must have a valid zone tier key for cross-zone comparison
8.152ms 0.002ms === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server request:RecomputeStats [/Table/104,/Min)
8.152ms 0.000ms [local proposal: {count: 1, duration 97µs}]
8.161ms 0.009ms event:server/node.go:1320 [n1] node received request: 1 RecomputeStats
8.186ms 0.025ms event:kv/kvserver/store_send.go:154 [n1,s1] executing RecomputeStats [/Table/104,/Min)
8.198ms 0.012ms event:kv/kvserver/replica_send.go:187 [n1,s1,r65/1:/{Table/104-Max}] read-write path
8.210ms 0.013ms event:kv/kvserver/concurrency/concurrency_manager.go:209 [n1,s1,r65/1:/{Table/104-Max}] sequencing request
8.217ms 0.007ms event:kv/kvserver/concurrency/concurrency_manager.go:290 [n1,s1,r65/1:/{Table/104-Max}] acquiring latches
8.231ms 0.013ms event:kv/kvserver/replica_write.go:167 [n1,s1,r65/1:/{Table/104-Max}] applied timestamp cache
8.239ms 0.008ms event:kv/kvserver/replica_write.go:407 [n1,s1,r65/1:/{Table/104-Max}] executing read-write batch
9.264ms 1.026ms event:kv/kvserver/replica_evaluate.go:508 [n1,s1,r65/1:/{Table/104-Max}] evaluated RecomputeStats command header:<key:"\360" > , txn=<nil> : resp=header:<> added_delta:<last_update_nanos:1692717351440167660 > , err=<nil>
9.279ms 0.014ms event:kv/kvserver/replica_proposal.go:965 [n1,s1,r65/1:/{Table/104-Max}] need consensus on write batch with op count=0
9.301ms 0.022ms event:kv/kvserver/replica_raft.go:125 [n1,s1,r65/1:/{Table/104-Max}] evaluated request
9.312ms 0.011ms event:kv/kvserver/replica_raft.go:170 [n1,s1,r65/1:/{Table/104-Max}] proposing command to write 0 new keys, 0 new values, 0 new intents, write batch size=14 bytes
9.322ms 0.010ms event:kv/kvserver/replica_raft.go:275 [n1,s1,r65/1:/{Table/104-Max}] acquiring proposal quota (128 bytes)
9.334ms 0.012ms event:kv/kvserver/replica_raft.go:431 [n1,s1,r65/1:/{Table/104-Max}] submitting proposal to proposal buffer
9.390ms 0.056ms event:kv/kvserver/replica_proposal_buf.go:601 [n1,s1,r65/1:/{Table/104-Max}] flushing proposal to Raft
9.450ms 0.060ms === operation:local proposal _verbose:1 node:1 store:1 range:65/1:/{Table/104-Max} raft:
9.475ms 0.025ms event:kv/kvserver/app_batch.go:121 [n1,s1,r65/1:/{Table/104-Max},raft] applying command
9.534ms 0.059ms event:kv/kvserver/replica_application_state_machine.go:176 [n1,s1,r65/1:/{Table/104-Max},raft] LocalResult (reply: (err: <nil>), *kvpb.RecomputeStatsResponse, #encountered intents: 0, #acquired locks: 0, #resolved locks: 0#updated txns: 0 #end txns: 0, GossipFirstRange:false MaybeGossipSystemConfig:false MaybeGossipSystemConfigIfHaveFailure:false MaybeAddToSplitQueue:false MaybeGossipNodeLiveness:<nil>
9.619ms 1.615ms event:kv/kvserver/store.go:3602 [n1,s1,r65/1:/{Table/104-Max}] processed: true (err: <nil>)
" to match "(?s)shouldQueue=false"
Test: TestProtectedTimestamps
panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/4d48402a71deafe4adff22980d19f276/logTestProtectedTimestamps1654883036
--- FAIL: TestProtectedTimestamps (19.93s)
Metadata
Metadata
Assignees
Labels
Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior.Broken test (automatically or manually discovered).Originated from a bot.KV TeamFailures and bugs on the master branch.Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked.