Skip to content

Commit

Permalink
kvcoord: Fix metrics tracking in mux rangefeed
Browse files Browse the repository at this point in the history 
Fix an observability bug in mux rangefeed which would
incorrectly count various rangefeed related metrics
(total ranges, catchup ranges, etc).

Fixes cockroachdb#106152
Fixes cockroachdb#106252

Release note: None
  • Loading branch information
Yevgeniy Miretskiy committed Jul 21, 2023
1 parent be21b3b commit bf6cd30
Show file tree
Hide file tree
Showing 5 changed files with 282 additions and 57 deletions.
1 change: 1 addition & 0 deletions pkg/kv/kvclient/kvcoord/BUILD.bazel
View file
Original file line number Diff line number Diff line change
Expand Up @@ -214,6 +214,7 @@ go_test(
"//pkg/util/randutil",
"//pkg/util/retry",
"//pkg/util/shuffle",
"//pkg/util/span",
"//pkg/util/stop",
"//pkg/util/syncutil",
"//pkg/util/timeutil",
Expand Down
31 changes: 21 additions & 10 deletions pkg/kv/kvclient/kvcoord/dist_sender.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -306,13 +306,18 @@ type DistSenderMetrics struct {
InLeaseTransferBackoffs *metric.Counter
RangeLookups *metric.Counter
SlowRPCs *metric.Gauge
RangefeedRanges *metric.Gauge
RangefeedCatchupRanges *metric.Gauge
RangefeedErrorCatchup *metric.Counter
RangefeedRestartRanges *metric.Counter
RangefeedRestartStuck *metric.Counter
MethodCounts [kvpb.NumMethods]*metric.Counter
ErrCounts [kvpb.NumErrors]*metric.Counter
DistSenderRangeFeedMetrics
}

// DistSenderRangeFeedMetrics is a set of rangefeed specific metrics.
type DistSenderRangeFeedMetrics struct {
RangefeedRanges *metric.Gauge
RangefeedCatchupRanges *metric.Gauge
RangefeedErrorCatchup *metric.Counter
RangefeedRestartRanges *metric.Counter
RangefeedRestartStuck *metric.Counter
}

func makeDistSenderMetrics() DistSenderMetrics {
Expand All @@ -334,11 +339,7 @@ func makeDistSenderMetrics() DistSenderMetrics {
InLeaseTransferBackoffs: metric.NewCounter(metaDistSenderInLeaseTransferBackoffsCount),
RangeLookups: metric.NewCounter(metaDistSenderRangeLookups),
SlowRPCs: metric.NewGauge(metaDistSenderSlowRPCs),
RangefeedRanges: metric.NewGauge(metaDistSenderRangefeedTotalRanges),
RangefeedCatchupRanges: metric.NewGauge(metaDistSenderRangefeedCatchupRanges),
RangefeedErrorCatchup: metric.NewCounter(metaDistSenderRangefeedErrorCatchupRanges),
RangefeedRestartRanges: metric.NewCounter(metaDistSenderRangefeedRestartRanges),
RangefeedRestartStuck: metric.NewCounter(metaDistSenderRangefeedRestartStuck),
DistSenderRangeFeedMetrics: makeDistSenderRangeFeedMetrics(),
}
for i := range m.MethodCounts {
method := kvpb.Method(i).String()
Expand All @@ -357,6 +358,16 @@ func makeDistSenderMetrics() DistSenderMetrics {
return m
}

func makeDistSenderRangeFeedMetrics() DistSenderRangeFeedMetrics {
return DistSenderRangeFeedMetrics{
RangefeedRanges: metric.NewGauge(metaDistSenderRangefeedTotalRanges),
RangefeedCatchupRanges: metric.NewGauge(metaDistSenderRangefeedCatchupRanges),
RangefeedErrorCatchup: metric.NewCounter(metaDistSenderRangefeedErrorCatchupRanges),
RangefeedRestartRanges: metric.NewCounter(metaDistSenderRangefeedRestartRanges),
RangefeedRestartStuck: metric.NewCounter(metaDistSenderRangefeedRestartStuck),
}
}

// updateCrossLocalityMetricsOnReplicaAddressedBatchRequest updates
// DistSenderMetrics for batch requests that have been divided and are currently
// forwarding to a specific replica for the corresponding range. The metrics
Expand Down
52 changes: 27 additions & 25 deletions pkg/kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -158,7 +158,7 @@ type activeMuxRangeFeed struct {
roachpb.ReplicaDescriptor
startAfter hlc.Timestamp

// cathchupRes is the catchup scan quota acquired upon the
// catchupRes is the catchup scan quota acquired upon the
// start of rangefeed.
// It is released when this stream receives first non-empty checkpoint
// (meaning: catchup scan completes).
Expand Down Expand Up @@ -211,7 +211,7 @@ func (m *rangefeedMuxer) startSingleRangeFeed(

// Register active mux range feed.
stream := &activeMuxRangeFeed{
activeRangeFeed: newActiveRangeFeed(span, startAfter, m.registry, m.ds.metrics.RangefeedRanges),
activeRangeFeed: newActiveRangeFeed(span, startAfter, m.registry, m.cfg.RangefeedRanges),
rSpan: rs,
startAfter: startAfter,
token: token,
Expand Down Expand Up @@ -241,7 +241,7 @@ func (s *activeMuxRangeFeed) start(ctx context.Context, m *rangefeedMuxer) error

{
// Before starting single rangefeed, acquire catchup scan quota.
catchupRes, err := acquireCatchupScanQuota(ctx, m.ds, m.catchupSem)
catchupRes, err := acquireCatchupScanQuota(ctx, &m.ds.st.SV, m.catchupSem, &m.cfg.DistSenderRangeFeedMetrics)
if err != nil {
return err
}
Expand Down Expand Up @@ -387,13 +387,19 @@ func (m *rangefeedMuxer) startNodeMuxRangeFeed(
recvErr = nil
}

toRestart := ms.close()

// make sure that the underlying error is not fatal. If it is, there is no
// reason to restart each rangefeed, so just bail out.
if _, err := handleRangefeedError(ctx, recvErr); err != nil {
// Regardless of an error, release any resources (i.e. metrics) still
// being held by active stream.
for _, s := range toRestart {
s.release()
}
return err
}

toRestart := ms.close()
if log.V(1) {
log.Infof(ctx, "mux to node %d restarted %d streams", ms.nodeID, len(toRestart))
}
Expand Down Expand Up @@ -429,8 +435,14 @@ func (m *rangefeedMuxer) receiveEventsFromNode(
continue
}

if m.cfg.knobs.onMuxRangefeedEvent != nil {
m.cfg.knobs.onMuxRangefeedEvent(event)
if m.cfg.knobs.onRangefeedEvent != nil {
skip, err := m.cfg.knobs.onRangefeedEvent(ctx, active.Span, &event.RangeFeedEvent)
if err != nil {
return err
}
if skip {
continue
}
}

switch t := event.GetValue().(type) {
Expand All @@ -451,7 +463,7 @@ func (m *rangefeedMuxer) receiveEventsFromNode(
case *kvpb.RangeFeedError:
log.VErrEventf(ctx, 2, "RangeFeedError: %s", t.Error.GoError())
if active.catchupRes != nil {
m.ds.metrics.RangefeedErrorCatchup.Inc(1)
m.cfg.RangefeedErrorCatchup.Inc(1)
}
ms.deleteStream(event.StreamID)
// Restart rangefeed on another goroutine. Restart might be a bit
Expand All @@ -473,7 +485,7 @@ func (m *rangefeedMuxer) receiveEventsFromNode(
}
}

// restarActiveRangeFeeds restarts one or more rangefeeds.
// restartActiveRangeFeeds restarts one or more rangefeeds.
func (m *rangefeedMuxer) restartActiveRangeFeeds(
ctx context.Context, reason error, toRestart []*activeMuxRangeFeed,
) error {
Expand All @@ -489,13 +501,7 @@ func (m *rangefeedMuxer) restartActiveRangeFeeds(
func (m *rangefeedMuxer) restartActiveRangeFeed(
ctx context.Context, active *activeMuxRangeFeed, reason error,
) error {
m.ds.metrics.RangefeedRestartRanges.Inc(1)

if log.V(1) {
log.Infof(ctx, "RangeFeed %s@%s (r%d, replica %s) disconnected with last checkpoint %s ago: %v",
active.Span, active.StartAfter, active.RangeID, active.ReplicaDescriptor,
timeutil.Since(active.Resolved.GoTime()), reason)
}
m.cfg.RangefeedRestartRanges.Inc(1)
active.setLastError(reason)

// Release catchup scan reservation if any -- we will acquire another
Expand All @@ -518,6 +524,12 @@ func (m *rangefeedMuxer) restartActiveRangeFeed(
return err
}

if log.V(1) {
log.Infof(ctx, "RangeFeed %s@%s (r%d, replica %s) disconnected with last checkpoint %s ago: %v (errInfo %v)",
active.Span, active.StartAfter, active.RangeID, active.ReplicaDescriptor,
timeutil.Since(active.Resolved.GoTime()), reason, errInfo)
}

if errInfo.evict {
active.resetRouting(ctx, rangecache.EvictionToken{})
}
Expand Down Expand Up @@ -587,13 +599,3 @@ func (c *muxStream) close() []*activeMuxRangeFeed {

return toRestart
}

// a test only option to modify mux rangefeed event.
func withOnMuxEvent(fn func(event *kvpb.MuxRangeFeedEvent)) RangeFeedOption {
return optionFunc(func(c *rangeFeedConfig) {
c.knobs.onMuxRangefeedEvent = fn
})
}

// TestingWithOnMuxEvent allow external tests access to the withOnMuxEvent option.
var TestingWithOnMuxEvent = withOnMuxEvent
72 changes: 57 additions & 15 deletions pkg/kv/kvclient/kvcoord/dist_sender_rangefeed.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,12 +89,17 @@ func maxConcurrentCatchupScans(sv *settings.Values) int {
}

type rangeFeedConfig struct {
DistSenderRangeFeedMetrics

useMuxRangeFeed bool
overSystemTable bool
withDiff bool

knobs struct {
onMuxRangefeedEvent func(event *kvpb.MuxRangeFeedEvent)
// onRangefeedEvent invoked on each rangefeed event.
// Returns boolean indicating if event should be skipped or an error
// indicating if rangefeed should terminate.
onRangefeedEvent func(ctx context.Context, s roachpb.Span, event *kvpb.RangeFeedEvent) (skip bool, _ error)
}
}

Expand Down Expand Up @@ -186,7 +191,9 @@ func (ds *DistSender) RangeFeedSpans(
return errors.AssertionFailedf("expected at least 1 span, got none")
}

var cfg rangeFeedConfig
cfg := rangeFeedConfig{
DistSenderRangeFeedMetrics: ds.metrics.DistSenderRangeFeedMetrics,
}
for _, opt := range opts {
opt.set(&cfg)
}
Expand Down Expand Up @@ -462,7 +469,7 @@ func (ds *DistSender) partialRangeFeed(
span := rs.AsRawSpanWithNoLocals()

// Register partial range feed with registry.
active := newActiveRangeFeed(span, startAfter, rr, ds.metrics.RangefeedRanges)
active := newActiveRangeFeed(span, startAfter, rr, cfg.RangefeedRanges)
defer active.release()

// Start a retry loop for sending the batch to the range.
Expand Down Expand Up @@ -503,7 +510,7 @@ func (ds *DistSender) partialRangeFeed(
if err != nil {
return err
}
ds.metrics.RangefeedRestartRanges.Inc(1)
cfg.RangefeedRestartRanges.Inc(1)
if errInfo.evict {
token.Evict(ctx)
token = rangecache.EvictionToken{}
Expand Down Expand Up @@ -586,18 +593,21 @@ func (a catchupAlloc) Release() {
}

func acquireCatchupScanQuota(
ctx context.Context, ds *DistSender, catchupSem *limit.ConcurrentRequestLimiter,
ctx context.Context,
sv *settings.Values,
catchupSem *limit.ConcurrentRequestLimiter,
m *DistSenderRangeFeedMetrics,
) (catchupAlloc, error) {
// Indicate catchup scan is starting; Before potentially blocking on a semaphore, take
// opportunity to update semaphore limit.
catchupSem.SetLimit(maxConcurrentCatchupScans(&ds.st.SV))
catchupSem.SetLimit(maxConcurrentCatchupScans(sv))
res, err := catchupSem.Begin(ctx)
if err != nil {
return nil, err
}
ds.metrics.RangefeedCatchupRanges.Inc(1)
m.RangefeedCatchupRanges.Inc(1)
return func() {
ds.metrics.RangefeedCatchupRanges.Dec(1)
m.RangefeedCatchupRanges.Dec(1)
res.Release()
}, nil
}
Expand Down Expand Up @@ -707,7 +717,7 @@ func (ds *DistSender) singleRangeFeed(

// Indicate catchup scan is starting; Before potentially blocking on a semaphore, take
// opportunity to update semaphore limit.
catchupRes, err := acquireCatchupScanQuota(ctx, ds, catchupSem)
catchupRes, err := acquireCatchupScanQuota(ctx, &ds.st.SV, catchupSem, &cfg.DistSenderRangeFeedMetrics)
if err != nil {
return hlc.Timestamp{}, err
}
Expand Down Expand Up @@ -776,11 +786,17 @@ func (ds *DistSender) singleRangeFeed(
log.VErrEventf(ctx, 2, "RPC error: %s", err)
if stuckWatcher.stuck() {
afterCatchUpScan := catchupRes == nil
return args.Timestamp, ds.handleStuckEvent(&args, afterCatchUpScan, stuckWatcher.threshold())
return args.Timestamp, handleStuckEvent(&args, afterCatchUpScan, stuckWatcher.threshold(), &cfg.DistSenderRangeFeedMetrics)
}
return args.Timestamp, err
}

if cfg.knobs.onRangefeedEvent != nil {
if _, err := cfg.knobs.onRangefeedEvent(ctx, span, event); err != nil {
return args.Timestamp, err
}
}

msg := RangeFeedMessage{RangeFeedEvent: event, RegisteredSpan: span}
switch t := event.GetValue().(type) {
case *kvpb.RangeFeedCheckpoint:
Expand All @@ -799,14 +815,14 @@ func (ds *DistSender) singleRangeFeed(
case *kvpb.RangeFeedError:
log.VErrEventf(ctx, 2, "RangeFeedError: %s", t.Error.GoError())
if catchupRes != nil {
ds.metrics.RangefeedErrorCatchup.Inc(1)
cfg.RangefeedErrorCatchup.Inc(1)
}
if stuckWatcher.stuck() {
// When the stuck watcher fired, and the rangefeed call is local,
// the remote might notice the cancellation first and return from
// Recv with an error that we need to special-case here.
afterCatchUpScan := catchupRes == nil
return args.Timestamp, ds.handleStuckEvent(&args, afterCatchUpScan, stuckWatcher.threshold())
return args.Timestamp, handleStuckEvent(&args, afterCatchUpScan, stuckWatcher.threshold(), &cfg.DistSenderRangeFeedMetrics)
}
return args.Timestamp, t.Error.GoError()
}
Expand All @@ -828,10 +844,13 @@ func connectionClass(sv *settings.Values) rpc.ConnectionClass {
return rpc.DefaultClass
}

func (ds *DistSender) handleStuckEvent(
args *kvpb.RangeFeedRequest, afterCatchupScan bool, threshold time.Duration,
func handleStuckEvent(
args *kvpb.RangeFeedRequest,
afterCatchupScan bool,
threshold time.Duration,
m *DistSenderRangeFeedMetrics,
) error {
ds.metrics.RangefeedRestartStuck.Inc(1)
m.RangefeedRestartStuck.Inc(1)
if afterCatchupScan {
telemetry.Count("rangefeed.stuck.after-catchup-scan")
} else {
Expand All @@ -842,3 +861,26 @@ func (ds *DistSender) handleStuckEvent(

// sentinel error returned when cancelling rangefeed when it is stuck.
var errRestartStuckRange = errors.New("rangefeed restarting due to inactivity")

// a test only option to modify mux rangefeed event.
func withOnRangefeedEvent(
fn func(ctx context.Context, s roachpb.Span, event *kvpb.RangeFeedEvent) (skip bool, _ error),
) RangeFeedOption {
return optionFunc(func(c *rangeFeedConfig) {
c.knobs.onRangefeedEvent = fn
})
}

// a test only option to specify metrics to use while executing this rangefeed.
func withRangeFeedMetrics(m DistSenderRangeFeedMetrics) RangeFeedOption {
return optionFunc(func(c *rangeFeedConfig) {
c.DistSenderRangeFeedMetrics = m
})
}

// Expose various testing knobs to kvcoord_test package.
var (
TestingWithOnRangefeedEvent = withOnRangefeedEvent
TestingWithRangeFeedMetrics = withRangeFeedMetrics
TestingMakeRangeFeedMetrics = makeDistSenderRangeFeedMetrics
)
Loading

0 comments on commit bf6cd30

Please sign in to comment.