Skip to content

Commit af9aa95

Browse files
committed
kvserver: allow logs from callbacks up to 15 replicas per updateReplicationGauges
Previously, logs from the decommission nudger were not gated by a vmodule and could become spammy when many replicas were decommissioned at a low nudger frequency. This commit introduces a per-store budget, allowing logs from callbacks for up to 15 replicas per updateReplicationGauges call. Drawbacks of this approach: - Replicas are not visited in a sorted order, so we may be opening the floodgates from 15 different replicas each iteration. - Once a replica is permitted to log, its future logs from callbacks are not restricted. - If EnqueueProblemRangeInReplicateQueueInterval is set too low, 1 and 2 may become worse. For 1, we could consider visit the replica set with WithReplicasInOrder. I'm not sure about the overhead here since updateReplicationGauges is called periodically when collecting metrics. Here are the reasons that I think this approach is acceptable for now: - onEnqueueResult is unlikely to be reinvoked for replicas already in the queue unless they are processing or in purgatory (both are short-lived states we want visibility into). Once processed, replicas are removed from the set. onProcessResult should be called at most twice. For replicas merely waiting in the queue, the callback is not invoked, since their priority should not be actively updated. - We could cap logging per maybeEnqueueProblemRange, but granting full logging permission for each replica simplifies reasoning and gives complete visibility for specific replias. - In practice, escalations show that slow decommissioning usually involves <15 ranges, and EnqueueProblemRangeInReplicateQueueInterval is typically large (~15 minutes).
1 parent 293983e commit af9aa95

File tree

2 files changed

+43
-15
lines changed

2 files changed

+43
-15
lines changed

pkg/kv/kvserver/replica.go

Lines changed: 32 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -2867,8 +2867,9 @@ func (r *Replica) RefreshLeaderlessWatcherUnavailableStateForTesting(
28672867
// manner via the replica scanner, see #130199. This functionality is disabled
28682868
// by default for this reason.
28692869
func (r *Replica) maybeEnqueueProblemRange(
2870-
ctx context.Context, now time.Time, leaseValid, isLeaseholder bool,
2870+
ctx context.Context, now time.Time, leaseValid, isLeaseholder bool, shouldLog bool,
28712871
) {
2872+
28722873
// The method expects the caller to provide whether the lease is valid and
28732874
// the replica is the leaseholder for the range, so that it can avoid
28742875
// unnecessary work. We expect this method to be called in the context of
@@ -2910,24 +2911,41 @@ func (r *Replica) maybeEnqueueProblemRange(
29102911
r.store.replicateQueue.AddAsyncWithCallback(ctx, r,
29112912
allocatorimpl.AllocatorReplaceDecommissioningVoter.Priority(), processCallback{
29122913
onEnqueueResult: func(indexOnHeap int, err error) {
2913-
if err != nil {
2914-
// TODO(wenyihu6): if we want to put these logs behind vmodule, move
2915-
// this function to another file so that we can avoid the spam on
2916-
// other logs.
2917-
log.KvDistribution.Infof(ctx,
2918-
"decommissioning nudger failed to enqueue range %v due to %v", r.Desc(), err)
2914+
if shouldLog {
2915+
if err != nil {
2916+
log.KvDistribution.Infof(ctx,
2917+
"decommissioning nudger failed to enqueue range %v due to %v", r.Desc(), err)
2918+
} else {
2919+
log.KvDistribution.Infof(ctx,
2920+
"decommissioning nudger successfully enqueued range %v at index %d", r.Desc(), indexOnHeap)
2921+
}
29192922
} else {
2920-
log.KvDistribution.Infof(ctx,
2921-
"decommissioning nudger successfully enqueued range %v at index %d", r.Desc(), indexOnHeap)
2923+
if err != nil {
2924+
log.KvDistribution.VInfof(ctx, 2,
2925+
"decommissioning nudger failed to enqueue range %v due to %v", r.Desc(), err)
2926+
} else {
2927+
log.KvDistribution.VInfof(ctx, 2,
2928+
"decommissioning nudger successfully enqueued range %v at index %d", r.Desc(), indexOnHeap)
2929+
}
29222930
}
29232931
},
29242932
onProcessResult: func(err error) {
2925-
if err != nil {
2926-
log.KvDistribution.Infof(ctx,
2927-
"decommissioning nudger failed to process range %v due to %v", r.Desc(), err)
2933+
if shouldLog {
2934+
if err != nil {
2935+
log.KvDistribution.Infof(ctx,
2936+
"decommissioning nudger failed to process range %v due to %v", r.Desc(), err)
2937+
} else {
2938+
log.KvDistribution.Infof(ctx,
2939+
"decommissioning nudger successfully processed replica %s", r.Desc())
2940+
}
29282941
} else {
2929-
log.KvDistribution.Infof(ctx,
2930-
"decommissioning nudger successfully processed replica %s", r.Desc())
2942+
if err != nil {
2943+
log.KvDistribution.VInfof(ctx, 2,
2944+
"decommissioning nudger failed to process range %v due to %v", r.Desc(), err)
2945+
} else {
2946+
log.KvDistribution.VInfof(ctx, 2,
2947+
"decommissioning nudger successfully processed replica %s", r.Desc())
2948+
}
29312949
}
29322950
},
29332951
})

pkg/kv/kvserver/store.go

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3403,6 +3403,12 @@ func (s *Store) updateReplicationGauges(ctx context.Context) error {
34033403
ioOverload, _ = s.ioThreshold.t.Score()
34043404
s.ioThreshold.Unlock()
34053405

3406+
// TODO(wenyihu6): it would be nicer if we can sort the replicas so that we
3407+
// can always get the nudger story on the same set of replicas, will this
3408+
// introduce a lot of overhead? For now, it seems fine since we usually see <
3409+
// 15 ranges on decommission stall.
3410+
var logBudgetOnDecommissioningNudger = 15
3411+
34063412
// We want to avoid having to read this multiple times during the replica
34073413
// visiting, so load it once up front for all nodes.
34083414
livenessMap := s.cfg.NodeLiveness.ScanNodeVitalityFromCache()
@@ -3472,7 +3478,11 @@ func (s *Store) updateReplicationGauges(ctx context.Context) error {
34723478
if metrics.Decommissioning {
34733479
// NB: Enqueue is disabled by default from here and throttled async if
34743480
// enabled.
3475-
rep.maybeEnqueueProblemRange(ctx, goNow, metrics.LeaseValid, metrics.Leaseholder)
3481+
shouldLog := logBudgetOnDecommissioningNudger > 0
3482+
if shouldLog {
3483+
logBudgetOnDecommissioningNudger--
3484+
}
3485+
rep.maybeEnqueueProblemRange(ctx, goNow, metrics.LeaseValid, metrics.Leaseholder, shouldLog)
34763486
decommissioningRangeCount++
34773487
}
34783488
}

0 commit comments

Comments
 (0)