diff --git a/logservice/logpuller/errors.go b/logservice/logpuller/errors.go index ad3c48a093..9e27c975ae 100644 --- a/logservice/logpuller/errors.go +++ b/logservice/logpuller/errors.go @@ -38,6 +38,17 @@ func (e *rpcCtxUnavailableErr) Error() string { e.verID.GetID(), e.verID.GetVer(), e.verID.GetConfVer()) } +type rpcCtxChangedError struct { + verID tikv.RegionVerID + from string + to string +} + +func (e *rpcCtxChangedError) Error() string { + return fmt.Sprintf("rpcCtx for region %v changed from %s to %s. ver:%v, confver:%v", + e.verID.GetID(), e.from, e.to, e.verID.GetVer(), e.verID.GetConfVer()) +} + type getStoreErr struct{} func (e *getStoreErr) Error() string { return "get store error" } diff --git a/logservice/logpuller/region_event_handler.go b/logservice/logpuller/region_event_handler.go index 7e96008c77..91c4466bd0 100644 --- a/logservice/logpuller/region_event_handler.go +++ b/logservice/logpuller/region_event_handler.go @@ -87,7 +87,8 @@ func (event regionEvent) mustFirstState() *regionFeedState { } type regionEventHandler struct { - subClient *subscriptionClient + eventSink *regionEventSink + failureHandler *regionFailureHandler } func (h *regionEventHandler) Path(event regionEvent) SubscriptionID { @@ -159,7 +160,7 @@ func (h *regionEventHandler) Handle(span *subscribedSpan, events ...regionEvent) metricConsumeKVEventsCallbackDurationAdvanceResolvedTs.Observe(time.Since(start).Seconds()) start = time.Now() - h.subClient.wakeSubscription(span.subID) + h.eventSink.Wake(span.subID) metricConsumeKVEventsCallbackDurationWakeSubscription.Observe(time.Since(start).Seconds()) }) // if not await, the wake callback will not be called, we need clear the cache manually. @@ -254,8 +255,8 @@ func (h *regionEventHandler) handleRegionError(state *regionFeedState) { zap.Error(err)) } if stepsToRemoved { - worker.takeRegionState(SubscriptionID(state.requestID), state.getRegionID()) - h.subClient.onRegionFail(newRegionErrorInfo(state.getRegionInfo(), err)) + worker.tracker.RemoveRegion(SubscriptionID(state.requestID), state.getRegionID()) + h.failureHandler.Report(newRegionErrorInfo(state.getRegionInfo(), err)) } } diff --git a/logservice/logpuller/region_event_handler_test.go b/logservice/logpuller/region_event_handler_test.go index e94d176ed0..daca162f77 100644 --- a/logservice/logpuller/region_event_handler_test.go +++ b/logservice/logpuller/region_event_handler_test.go @@ -79,6 +79,7 @@ func TestHandleEventEntryEventOutOfOrder(t *testing.T) { worker := ®ionRequestWorker{ requestCache: &requestCache{}, + tracker: newRegionTracker(0), } region := newRegionInfo( tikv.RegionVerID{}, @@ -88,8 +89,7 @@ func TestHandleEventEntryEventOutOfOrder(t *testing.T) { false, ) region.lockedRangeState = ®ionlock.LockedRangeState{} - state := newRegionFeedState(region, 1, worker) - state.start() + state := newRegionFeedState(region, 1, worker, nil) // Receive prewrite2 with empty value. { @@ -218,9 +218,9 @@ func TestHandleResolvedTs(t *testing.T) { subID1 := SubscriptionID(1) worker := ®ionRequestWorker{ requestCache: &requestCache{}, + tracker: newRegionTracker(0), } - state1 := newRegionFeedState(regionInfo{verID: tikv.NewRegionVerID(1, 1, 1)}, uint64(subID1), worker) - state1.start() + state1 := newRegionFeedState(regionInfo{verID: tikv.NewRegionVerID(1, 1, 1)}, uint64(subID1), worker, nil) { span := heartbeatpb.TableSpan{ TableID: 100, @@ -243,8 +243,7 @@ func TestHandleResolvedTs(t *testing.T) { } subID2 := SubscriptionID(2) - state2 := newRegionFeedState(regionInfo{verID: tikv.NewRegionVerID(2, 2, 2)}, uint64(subID2), worker) - state2.start() + state2 := newRegionFeedState(regionInfo{verID: tikv.NewRegionVerID(2, 2, 2)}, uint64(subID2), worker, nil) { span := heartbeatpb.TableSpan{ TableID: 100, @@ -267,8 +266,7 @@ func TestHandleResolvedTs(t *testing.T) { } subID3 := SubscriptionID(3) - state3 := newRegionFeedState(regionInfo{verID: tikv.NewRegionVerID(3, 3, 3)}, uint64(subID3), worker) - state3.start() + state3 := newRegionFeedState(regionInfo{verID: tikv.NewRegionVerID(3, 3, 3)}, uint64(subID3), worker, nil) { span := heartbeatpb.TableSpan{ TableID: 100, @@ -361,6 +359,8 @@ func TestHandleResolvedTsThrottled(t *testing.T) { advanceInterval: 100, } span.lastAdvanceTime.Store(0) + worker := ®ionRequestWorker{} + worker.tracker = newRegionTracker(0) state := newRegionFeedState( regionInfo{ verID: tikv.NewRegionVerID(1, 1, 1), @@ -368,9 +368,9 @@ func TestHandleResolvedTsThrottled(t *testing.T) { lockedRangeState: res1.LockedRangeState, }, 1, + worker, nil, ) - state.start() require.Equal(t, uint64(200), handleResolvedTs(span, state, 300)) } diff --git a/logservice/logpuller/region_event_sink.go b/logservice/logpuller/region_event_sink.go new file mode 100644 index 0000000000..0a90527d4b --- /dev/null +++ b/logservice/logpuller/region_event_sink.go @@ -0,0 +1,133 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "context" + "sync" + "sync/atomic" + + "github.com/pingcap/log" + "github.com/pingcap/ticdc/utils/dynstream" + "go.uber.org/zap" +) + +type regionEventSink struct { + ctx context.Context + ds dynstream.DynamicStream[int, SubscriptionID, regionEvent, *subscribedSpan, *regionEventHandler] + + mu sync.Mutex + cond *sync.Cond + paused atomic.Bool +} + +func newRegionEventSink(ctx context.Context, failureHandler *regionFailureHandler) *regionEventSink { + sink := ®ionEventSink{ctx: ctx} + sink.cond = sync.NewCond(&sink.mu) + + option := dynstream.NewOption() + // Note: it is max batch size of the kv sent from tikv(not committed rows) + option.BatchCount = 1024 + // TODO: Set `UseBuffer` to true until we refactor the `regionEventHandler.Handle` method so that it doesn't call any method of the dynamic stream. Currently, if `UseBuffer` is set to false, there will be a deadlock: + // ds.handleLoop fetch events from `ch` -> regionEventHandler.Handle -> ds.RemovePath -> send event to `ch` + option.UseBuffer = true + option.EnableMemoryControl = true + ds := dynstream.NewParallelDynamicStream( + "log-puller", + ®ionEventHandler{eventSink: sink, failureHandler: failureHandler}, + option, + ) + ds.Start() + sink.ds = ds + return sink +} + +func (s *regionEventSink) AddPath(rt *subscribedSpan) { + areaSetting := dynstream.NewAreaSettingsWithMaxPendingSize(1*1024*1024*1024, dynstream.MemoryControlForPuller, "logPuller") // 1GB + if err := s.ds.AddPath(rt.subID, rt, areaSetting); err != nil { + log.Warn("subscription client add path failed", + zap.Uint64("subscriptionID", uint64(rt.subID)), + zap.Error(err)) + } +} + +func (s *regionEventSink) RemovePath(subID SubscriptionID) error { + return s.ds.RemovePath(subID) +} + +func (s *regionEventSink) Wake(subID SubscriptionID) { + s.ds.Wake(subID) +} + +func (s *regionEventSink) Push(subID SubscriptionID, event regionEvent) { + // fast path + if !s.paused.Load() { + s.ds.Push(subID, event) + return + } + // slow path: wait until paused is false + s.mu.Lock() + for s.paused.Load() { + select { + case <-s.ctx.Done(): + s.mu.Unlock() + return + default: + s.cond.Wait() + } + } + s.mu.Unlock() + s.ds.Push(subID, event) +} + +func (s *regionEventSink) Run(ctx context.Context) error { + return s.handleFeedback(ctx) +} + +func (s *regionEventSink) handleFeedback(ctx context.Context) error { + for { + select { + case <-ctx.Done(): + return nil + case feedback := <-s.ds.Feedback(): + switch feedback.FeedbackType { + case dynstream.PauseArea: + s.mu.Lock() + s.paused.Store(true) + s.mu.Unlock() + log.Info("subscription client pause push region event") + case dynstream.ResumeArea: + s.mu.Lock() + s.paused.Store(false) + s.cond.Broadcast() + s.mu.Unlock() + log.Info("subscription client resume push region event") + case dynstream.ReleasePath, dynstream.ResumePath: + // Ignore it, because it is no need to pause and resume a path in puller. + } + } + } +} + +func (s *regionEventSink) Metrics() dynstream.Metrics[int, SubscriptionID] { + return s.ds.GetMetrics() +} + +func (s *regionEventSink) Close() { + s.mu.Lock() + s.paused.Store(false) + s.cond.Broadcast() + s.mu.Unlock() + s.ds.Close() +} diff --git a/logservice/logpuller/region_failure_handler.go b/logservice/logpuller/region_failure_handler.go new file mode 100644 index 0000000000..912b263378 --- /dev/null +++ b/logservice/logpuller/region_failure_handler.go @@ -0,0 +1,303 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "context" + "sync" + "time" + + "github.com/pingcap/log" + "github.com/pingcap/ticdc/heartbeatpb" + "github.com/pingcap/ticdc/pkg/errors" + "github.com/pingcap/ticdc/pkg/metrics" + "github.com/tikv/client-go/v2/tikv" + "go.uber.org/zap" +) + +const ( + // TiCDC always interacts with region leader, every time something goes wrong, + // failed region will be reloaded via `BatchLoadRegionsWithKeyRange` API. So we + // don't need to force reload region anymore. + regionScheduleReload = false +) + +var ( + metricFeedNotLeaderCounter = metrics.EventFeedErrorCounter.WithLabelValues("NotLeader") + metricFeedEpochNotMatchCounter = metrics.EventFeedErrorCounter.WithLabelValues("EpochNotMatch") + metricFeedRegionNotFoundCounter = metrics.EventFeedErrorCounter.WithLabelValues("RegionNotFound") + metricFeedDuplicateRequestCounter = metrics.EventFeedErrorCounter.WithLabelValues("DuplicateRequest") + metricFeedUnknownErrorCounter = metrics.EventFeedErrorCounter.WithLabelValues("Unknown") + metricFeedRPCCtxUnavailable = metrics.EventFeedErrorCounter.WithLabelValues("RPCCtxUnavailable") + metricGetStoreErr = metrics.EventFeedErrorCounter.WithLabelValues("GetStoreErr") + metricStoreSendRequestErr = metrics.EventFeedErrorCounter.WithLabelValues("SendRequestToStore") + metricKvIsBusyCounter = metrics.EventFeedErrorCounter.WithLabelValues("KvIsBusy") + metricKvCongestedCounter = metrics.EventFeedErrorCounter.WithLabelValues("KvCongested") +) + +type regionFailureHandler struct { + cache *errCache + + upstream *upstreamHandle + onTableDrained func(*subscribedSpan) + scheduleRegionRequest func(context.Context, regionInfo, TaskType) + scheduleRangeRequest func(context.Context, heartbeatpb.TableSpan, *subscribedSpan, bool, TaskType) +} + +func newRegionFailureHandler( + upstream *upstreamHandle, + onTableDrained func(*subscribedSpan), + scheduleRegionRequest func(context.Context, regionInfo, TaskType), + scheduleRangeRequest func(context.Context, heartbeatpb.TableSpan, *subscribedSpan, bool, TaskType), +) *regionFailureHandler { + return ®ionFailureHandler{ + cache: newErrCache(), + upstream: upstream, + onTableDrained: onTableDrained, + scheduleRegionRequest: scheduleRegionRequest, + scheduleRangeRequest: scheduleRangeRequest, + } +} + +// Report admits a region failure into the recovery pipeline. It releases the +// corresponding range lock before enqueueing the failure so new range tasks are +// not blocked by stale region ownership. +func (r *regionFailureHandler) Report(errInfo regionErrorInfo) { + if errInfo.subscribedSpan.rangeLock.UnlockRange( + errInfo.span.StartKey, errInfo.span.EndKey, + errInfo.verID.GetID(), errInfo.verID.GetVer(), errInfo.resolvedTs()) { + r.onTableDrained(errInfo.subscribedSpan) + return + } + r.cache.add(errInfo) +} + +func (r *regionFailureHandler) Run(ctx context.Context) error { + ticker := time.NewTicker(10 * time.Millisecond) + defer ticker.Stop() + handlePendingFailures := func() error { + for { + batch := r.cache.popBatch(errCacheDispatchBatchSize) + for _, errInfo := range batch { + select { + case <-ctx.Done(): + log.Info("subscription client handle errors and exit") + return ctx.Err() + default: + } + if err := r.handleError(ctx, errInfo); err != nil { + return err + } + } + if len(batch) < errCacheDispatchBatchSize { + return nil + } + } + } + for { + select { + case <-ctx.Done(): + log.Info("subscription client handle errors and exit") + return ctx.Err() + case <-ticker.C: + if err := handlePendingFailures(); err != nil { + return err + } + case <-r.cache.notify: + if err := handlePendingFailures(); err != nil { + return err + } + } + } +} + +func (r *regionFailureHandler) handleError(ctx context.Context, errInfo regionErrorInfo) error { + err := errors.Cause(errInfo.err) + //nolint:errorlint // errors.Cause unwraps repository errors before the concrete type check. + if _, requestCancelled := err.(*requestCancelledErr); !requestCancelled { + log.Debug("cdc region error", + zap.Uint64("subscriptionID", uint64(errInfo.subscribedSpan.subID)), + zap.Uint64("regionID", errInfo.verID.GetID()), + zap.Error(err)) + } + + //nolint:errorlint // converting large type switch to errors.As is a significant refactor + switch eerr := err.(type) { + case *eventError: + innerErr := eerr.err + if notLeader := innerErr.GetNotLeader(); notLeader != nil { + metricFeedNotLeaderCounter.Inc() + r.upstream.regionCache.UpdateLeader(errInfo.verID, notLeader.GetLeader(), errInfo.rpcCtx.AccessIdx) + r.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) + return nil + } + if innerErr.GetEpochNotMatch() != nil { + metricFeedEpochNotMatchCounter.Inc() + r.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) + return nil + } + if innerErr.GetRegionNotFound() != nil { + metricFeedRegionNotFoundCounter.Inc() + r.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) + return nil + } + if innerErr.GetCongested() != nil { + metricKvCongestedCounter.Inc() + r.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskLowPrior) + return nil + } + if innerErr.GetServerIsBusy() != nil { + metricKvIsBusyCounter.Inc() + r.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskLowPrior) + return nil + } + if duplicated := innerErr.GetDuplicateRequest(); duplicated != nil { + // TODO(qupeng): It's better to add a new machanism to deregister one region. + metricFeedDuplicateRequestCounter.Inc() + return errors.New("duplicate request") + } + if compatibility := innerErr.GetCompatibility(); compatibility != nil { + return errors.ErrVersionIncompatible.GenWithStackByArgs(compatibility) + } + if mismatch := innerErr.GetClusterIdMismatch(); mismatch != nil { + return errors.ErrClusterIDMismatch.GenWithStackByArgs(mismatch.Current, mismatch.Request) + } + + log.Warn("empty or unknown cdc error", + zap.Uint64("subscriptionID", uint64(errInfo.subscribedSpan.subID)), + zap.Stringer("error", innerErr)) + metricFeedUnknownErrorCounter.Inc() + r.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) + return nil + case *rpcCtxUnavailableErr: + metricFeedRPCCtxUnavailable.Inc() + r.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) + return nil + case *rpcCtxChangedError: + r.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) + return nil + case *getStoreErr: + metricGetStoreErr.Inc() + bo := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) + // cannot get the store the region belongs to, so we need to reload the region. + r.upstream.regionCache.OnSendFail(bo, errInfo.rpcCtx, true, err) + r.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) + return nil + case *storeStreamErr: + metricStoreSendRequestErr.Inc() + bo := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) + r.upstream.regionCache.OnSendFail(bo, errInfo.rpcCtx, regionScheduleReload, err) + r.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) + return nil + case *requestCancelledErr: + // the corresponding subscription has been unsubscribed, just ignore. + return nil + default: + // TODO(qupeng): for some errors it's better to just deregister the region from TiKVs. + log.Warn("subscription client meets an internal error, fail the changefeed", + zap.Uint64("subscriptionID", uint64(errInfo.subscribedSpan.subID)), + zap.Error(err)) + return err + } +} + +type errCache struct { + sync.Mutex + cache []regionErrorInfo + errCh chan regionErrorInfo + notify chan struct{} +} + +const errCacheDispatchBatchSize = 1024 + +func newErrCache() *errCache { + return &errCache{ + cache: make([]regionErrorInfo, 0, 1024), + errCh: make(chan regionErrorInfo, 4096), + notify: make(chan struct{}, 1024), + } +} + +func (e *errCache) add(errInfo regionErrorInfo) { + e.Lock() + defer e.Unlock() + e.cache = append(e.cache, errInfo) + select { + case e.notify <- struct{}{}: + default: + } +} + +func (e *errCache) popBatch(limit int) []regionErrorInfo { + e.Lock() + defer e.Unlock() + if len(e.cache) == 0 { + return nil + } + if limit <= 0 || limit > len(e.cache) { + limit = len(e.cache) + } + batch := make([]regionErrorInfo, limit) + copy(batch, e.cache[:limit]) + clear(e.cache[:limit]) + if limit == len(e.cache) { + e.cache = e.cache[:0] + } else { + e.cache = e.cache[limit:] + } + return batch +} + +func (e *errCache) dispatchBatch(ctx context.Context, limit int) (int, error) { + batch := e.popBatch(limit) + for _, errInfo := range batch { + select { + case <-ctx.Done(): + log.Info("subscription client dispatch err cache done") + return 0, ctx.Err() + case e.errCh <- errInfo: + } + } + return len(batch), nil +} + +func (e *errCache) dispatch(ctx context.Context) error { + ticker := time.NewTicker(10 * time.Millisecond) + defer ticker.Stop() + sendToErrCh := func() error { + for { + n, err := e.dispatchBatch(ctx, errCacheDispatchBatchSize) + if err != nil { + return err + } + if n < errCacheDispatchBatchSize { + return nil + } + } + } + for { + select { + case <-ctx.Done(): + return ctx.Err() + case <-ticker.C: + if err := sendToErrCh(); err != nil { + return err + } + case <-e.notify: + if err := sendToErrCh(); err != nil { + return err + } + } + } +} diff --git a/logservice/logpuller/priority_task.go b/logservice/logpuller/region_priority_task.go similarity index 62% rename from logservice/logpuller/priority_task.go rename to logservice/logpuller/region_priority_task.go index 68ef9e885d..9e954526b1 100644 --- a/logservice/logpuller/priority_task.go +++ b/logservice/logpuller/region_priority_task.go @@ -42,67 +42,50 @@ func (t TaskType) String() string { return fmt.Sprintf("%d", t) } -// PriorityTask is the interface for priority-based tasks -// It implements heap.Item interface -type PriorityTask interface { - // Priority returns the priority value, lower value means higher priority - Priority() int - - // GetRegionInfo returns the underlying regionInfo - GetRegionInfo() regionInfo - - // heap.Item interface methods - SetHeapIndex(int) - GetHeapIndex() int - LessThan(PriorityTask) bool -} - -// regionPriorityTask implements PriorityTask interface +// regionPriorityTask is a heap item for region scheduling. +// Lower priority values are popped first. The priority value is calculated when +// the task is created, so queued tasks do not rely on heap reordering as time +// passes or resolved-ts changes. type regionPriorityTask struct { taskType TaskType + priority int + seq uint64 createTime time.Time regionInfo regionInfo heapIndex int // for heap.Item interface - currentTs uint64 } -// NewRegionPriorityTask creates a new priority task for region -func NewRegionPriorityTask(taskType TaskType, regionInfo regionInfo, currentTs uint64) PriorityTask { +// newRegionPriorityTask creates a new priority task for region. +func newRegionPriorityTask(taskType TaskType, regionInfo regionInfo, currentTs uint64, seq uint64) *regionPriorityTask { return ®ionPriorityTask{ taskType: taskType, + priority: calculateRegionTaskPriority(taskType, regionInfo, currentTs), + seq: seq, createTime: time.Now(), regionInfo: regionInfo, heapIndex: 0, // 0 means not in heap - currentTs: currentTs, } } -// Priority calculates the priority based on task type and wait time -// Lower value means higher priority -func (pt *regionPriorityTask) Priority() int { - // Base priority based on task type +func calculateRegionTaskPriority(taskType TaskType, regionInfo regionInfo, currentTs uint64) int { basePriority := 0 - switch pt.taskType { + switch taskType { case TaskHighPrior: basePriority = highPriorityBase // Highest priority case TaskLowPrior: basePriority = lowPriorityBase // Lowest priority } - // Add time-based priority bonus - // Wait time in seconds, longer wait time means higher priority (lower value) - waitTime := time.Since(pt.createTime) - timeBonus := int(waitTime.Seconds()) - // ResolvedTsLag in seconds, longer lag means lower priority (higher value) - resolvedTsLag := oracle.GetTimeFromTS(pt.currentTs).Sub(oracle.GetTimeFromTS(pt.regionInfo.subscribedSpan.resolvedTs.Load())) + resolvedTsLag := oracle.GetTimeFromTS(currentTs).Sub(oracle.GetTimeFromTS(regionInfo.subscribedSpan.resolvedTs.Load())) resolvedTsLagPenalty := int(resolvedTsLag.Seconds()) - priority := basePriority - timeBonus + resolvedTsLagPenalty - if priority < 0 { - priority = 0 - } - return priority + return max(basePriority+resolvedTsLagPenalty, 0) +} + +// Priority returns the fixed priority value, lower value means higher priority. +func (pt *regionPriorityTask) Priority() int { + return pt.priority } // GetRegionInfo returns the underlying regionInfo @@ -121,7 +104,10 @@ func (pt *regionPriorityTask) GetHeapIndex() int { } // LessThan implements heap.Item interface -// Returns true if this task has higher priority (lower priority value) than the other task -func (pt *regionPriorityTask) LessThan(other PriorityTask) bool { - return pt.Priority() < other.Priority() +// Returns true if this task has higher priority (lower priority value) than the other task. +func (pt *regionPriorityTask) LessThan(other *regionPriorityTask) bool { + if pt.priority != other.priority { + return pt.priority < other.priority + } + return pt.seq < other.seq } diff --git a/logservice/logpuller/priority_task_test.go b/logservice/logpuller/region_priority_task_test.go similarity index 79% rename from logservice/logpuller/priority_task_test.go rename to logservice/logpuller/region_priority_task_test.go index d8b3f26d48..226d12b216 100644 --- a/logservice/logpuller/priority_task_test.go +++ b/logservice/logpuller/region_priority_task_test.go @@ -35,35 +35,30 @@ func TestPriorityCalculationLogic(t *testing.T) { name string taskType TaskType resolvedTsOffsetSeconds int64 // Offset relative to currentTs (negative means resolvedTs is older) - waitTimeSeconds int // Task wait time description string }{ { name: "high_priority_new_resolvedTs", taskType: TaskHighPrior, resolvedTsOffsetSeconds: -5, // resolvedTs is 5 seconds earlier than currentTs - waitTimeSeconds: 10, // Waited for 10 seconds description: "High priority task with newer resolvedTs", }, { name: "high_priority_old_resolvedTs", taskType: TaskHighPrior, resolvedTsOffsetSeconds: -30, // resolvedTs is 30 seconds earlier than currentTs - waitTimeSeconds: 10, // Waited for 10 seconds description: "High priority task with older resolvedTs", }, { name: "low_priority_new_resolvedTs", taskType: TaskLowPrior, resolvedTsOffsetSeconds: -5, // resolvedTs is 5 seconds earlier than currentTs - waitTimeSeconds: 10, // Waited for 10 seconds description: "Low priority task with newer resolvedTs", }, { name: "low_priority_old_resolvedTs", taskType: TaskLowPrior, resolvedTsOffsetSeconds: -30, // resolvedTs is 30 seconds earlier than currentTs - waitTimeSeconds: 10, // Waited for 10 seconds description: "Low priority task with older resolvedTs", }, } @@ -77,8 +72,7 @@ func TestPriorityCalculationLogic(t *testing.T) { resolvedTime := oracle.GetTimeFromTS(currentTs).Add(time.Duration(tt.resolvedTsOffsetSeconds) * time.Second) resolvedTs := oracle.GoTimeToTS(resolvedTime) - // Simulate priority calculation logic - priority := calculatePriorityDirectly(tt.taskType, currentTs, resolvedTs, tt.waitTimeSeconds) + priority := calculatePriorityDirectly(tt.taskType, currentTs, resolvedTs) t.Logf("%s: Priority = %d", tt.description, priority) priorities = append(priorities, priority) @@ -114,32 +108,20 @@ func TestPriorityCalculationLogic(t *testing.T) { }) } -// calculatePriorityDirectly directly calculates priority for testing -// Copies the logic from regionPriorityTask.Priority() -func calculatePriorityDirectly(taskType TaskType, currentTs, resolvedTs uint64, waitTimeSeconds int) int { - // Base priority based on task type +// calculatePriorityDirectly directly calculates priority for testing. +func calculatePriorityDirectly(taskType TaskType, currentTs, resolvedTs uint64) int { basePriority := 0 switch taskType { case TaskHighPrior: - basePriority = highPriorityBase // 1200 + basePriority = highPriorityBase case TaskLowPrior: - basePriority = lowPriorityBase // 3600 + basePriority = lowPriorityBase } - // Add time-based priority bonus - // Wait time in seconds, longer wait time means higher priority (lower value) - timeBonus := waitTimeSeconds - - // Calculate resolvedTs lag resolvedTsLag := oracle.GetTimeFromTS(currentTs).Sub(oracle.GetTimeFromTS(resolvedTs)) resolvedTsLagBonus := int(resolvedTsLag.Seconds()) - priority := basePriority - timeBonus + resolvedTsLagBonus - - if priority < 0 { - priority = 0 - } - return priority + return max(basePriority+resolvedTsLagBonus, 0) } func TestResolvedTsLagLogic(t *testing.T) { @@ -161,8 +143,8 @@ func TestResolvedTsLagLogic(t *testing.T) { require.Less(t, lag2, lag1, "newer resolvedTs should have smaller lag") // Calculate the impact on priority - priority1 := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs1, 5) - priority2 := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs2, 5) + priority1 := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs1) + priority2 := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs2) t.Logf("Priority with resolvedTs 10 seconds old: %d", priority1) t.Logf("Priority with resolvedTs 1 second old: %d", priority2) @@ -183,28 +165,28 @@ func TestEdgeCases(t *testing.T) { lag := oracle.GetTimeFromTS(currentTs).Sub(oracle.GetTimeFromTS(resolvedTs)) t.Logf("resolvedTs in the future 5 seconds, lag = %v (%.0f seconds)", lag, lag.Seconds()) - priority := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs, 5) + priority := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs) t.Logf("resolvedTs in the future priority: %d", priority) require.GreaterOrEqual(t, priority, 0, "priority should not be less than 0") }) - t.Run("different wait time impact", func(t *testing.T) { + t.Run("priority is stable after task creation", func(t *testing.T) { resolvedTs := oracle.GoTimeToTS(currentTime.Add(-10 * time.Second)) + subscribedSpan := &subscribedSpan{} + subscribedSpan.resolvedTs.Store(resolvedTs) + regionInfo := regionInfo{subscribedSpan: subscribedSpan} - priority1 := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs, 2) - priority2 := calculatePriorityDirectly(TaskHighPrior, currentTs, resolvedTs, 10) - - t.Logf("wait 2 seconds priority: %d", priority1) - t.Logf("wait 10 seconds priority: %d", priority2) + task := newRegionPriorityTask(TaskHighPrior, regionInfo, currentTs, 1) + priority := task.Priority() + subscribedSpan.resolvedTs.Store(currentTs) - // wait time longer task priority should be higher - require.Less(t, priority2, priority1, "wait time longer task priority should be higher") + require.Equal(t, priority, task.Priority()) }) } func TestRegionPriorityTaskQueueOrder(t *testing.T) { - queue := priorityqueue.New[PriorityTask]() + queue := priorityqueue.New[*regionPriorityTask]() ctx := t.Context() currentTs := oracle.GoTimeToTS(time.Now()) @@ -222,25 +204,25 @@ func TestRegionPriorityTaskQueueOrder(t *testing.T) { subscribedSpan: subscribedSpan, } - errorTask := NewRegionPriorityTask(TaskHighPrior, regionInfo, currentTs+1) - highTask := NewRegionPriorityTask(TaskHighPrior, regionInfo, currentTs) - lowTask := NewRegionPriorityTask(TaskLowPrior, regionInfo, currentTs) + firstHighTask := newRegionPriorityTask(TaskHighPrior, regionInfo, currentTs, 1) + secondHighTask := newRegionPriorityTask(TaskHighPrior, regionInfo, currentTs, 2) + lowTask := newRegionPriorityTask(TaskLowPrior, regionInfo, currentTs, 3) require.True(t, queue.Push(lowTask)) - require.True(t, queue.Push(errorTask)) - require.True(t, queue.Push(highTask)) + require.True(t, queue.Push(secondHighTask)) + require.True(t, queue.Push(firstHighTask)) first, err := queue.Pop(ctx) require.NoError(t, err) - require.Equal(t, TaskHighPrior, first.(*regionPriorityTask).taskType) + require.Same(t, firstHighTask, first) second, err := queue.Pop(ctx) require.NoError(t, err) - require.Equal(t, TaskHighPrior, second.(*regionPriorityTask).taskType) + require.Same(t, secondHighTask, second) third, err := queue.Pop(ctx) require.NoError(t, err) - require.Equal(t, TaskLowPrior, third.(*regionPriorityTask).taskType) + require.Same(t, lowTask, third) require.Equal(t, 0, queue.Len()) } diff --git a/logservice/logpuller/region_req_cache.go b/logservice/logpuller/region_req_cache.go deleted file mode 100644 index b4478cab07..0000000000 --- a/logservice/logpuller/region_req_cache.go +++ /dev/null @@ -1,341 +0,0 @@ -// Copyright 2025 PingCAP, Inc. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// See the License for the specific language governing permissions and -// limitations under the License. - -package logpuller - -import ( - "context" - "sync" - "time" - - "github.com/pingcap/log" - "github.com/pingcap/ticdc/pkg/metrics" - "go.uber.org/atomic" - "go.uber.org/zap" -) - -const ( - checkStaleRequestInterval = time.Second * 10 - requestGCLifeTime = time.Minute * 180 - addReqRetryInterval = time.Millisecond * 1 - addReqRetryLimit = 3 - abnormalRequestDurationInSec = 60 * 60 * 2 // 2 hours -) - -// regionReq represents a wrapped region request with state -type regionReq struct { - regionInfo regionInfo - createTime time.Time -} - -func newRegionReq(region regionInfo) regionReq { - return regionReq{ - regionInfo: region, - createTime: time.Now(), - } -} - -func (r *regionReq) isStale() bool { - return time.Since(r.createTime) > requestGCLifeTime -} - -// requestCache manages region requests with flow control -type requestCache struct { - // pending requests waiting to be sent - pendingQueue chan regionReq - - // sent requests waiting for initialization (subscriptionID -> regions -> regionReq) - sentRequests struct { - sync.RWMutex - regionReqs map[SubscriptionID]map[uint64]regionReq - } - - // pendingCount is a flow control slot counter. - // A slot is acquired when a request is successfully enqueued into pendingQueue (see add), - // and is released when the request is finished/removed (resolve/markStopped/markDone/clear). - // pop and markSent don't change it. If markSent overwrites an existing request for the same region, - // it will release a slot for the replaced request to avoid leaking pendingCount. - pendingCount atomic.Int64 - // maximum number of pending requests allowed - maxPendingCount int64 - - // channel to signal when space becomes available - spaceAvailable chan struct{} - - lastCheckStaleRequestTime atomic.Time -} - -func newRequestCache(maxPendingCount int) *requestCache { - res := &requestCache{ - pendingQueue: make(chan regionReq, maxPendingCount), // Large buffer to reduce blocking - sentRequests: struct { - sync.RWMutex - regionReqs map[SubscriptionID]map[uint64]regionReq - }{regionReqs: make(map[SubscriptionID]map[uint64]regionReq)}, - pendingCount: atomic.Int64{}, - maxPendingCount: int64(maxPendingCount), - spaceAvailable: make(chan struct{}, 16), // Buffered to avoid blocking - } - - res.lastCheckStaleRequestTime.Store(time.Now()) - return res -} - -// add adds a new region request to the cache -// It blocks if pendingCount >= maxPendingCount until there's space or ctx is cancelled -func (c *requestCache) add(ctx context.Context, region regionInfo, force bool) (bool, error) { - start := time.Now() - ticker := time.NewTicker(addReqRetryInterval) - defer ticker.Stop() - addReqRetryLimit := addReqRetryLimit - - for { - current := c.pendingCount.Load() - if current < c.maxPendingCount || force { - // Try to add the request - req := newRegionReq(region) - select { - case <-ctx.Done(): - return false, ctx.Err() - case c.pendingQueue <- req: - c.pendingCount.Inc() - cost := time.Since(start) - metrics.SubscriptionClientAddRegionRequestDuration.Observe(cost.Seconds()) - return true, nil - case <-ticker.C: - addReqRetryLimit-- - if addReqRetryLimit <= 0 { - return false, nil - } - continue - } - } - - // Wait for space to become available - select { - case <-ticker.C: - addReqRetryLimit-- - if addReqRetryLimit <= 0 { - return false, nil - } - continue - case <-c.spaceAvailable: - continue - case <-ctx.Done(): - return false, ctx.Err() - } - } -} - -// pop gets the next pending request. -// Note: it doesn't change pendingCount. The slot acquired in add() should be released later -// (e.g. resolve/markStopped/markDone). -func (c *requestCache) pop(ctx context.Context) (regionReq, error) { - select { - case req := <-c.pendingQueue: - return req, nil - case <-ctx.Done(): - return regionReq{}, ctx.Err() - } -} - -// markSent marks a request as sent and adds it to sent requests. -// It doesn't change pendingCount: the slot is released when the request is finished/removed. -func (c *requestCache) markSent(req regionReq) { - c.sentRequests.Lock() - defer c.sentRequests.Unlock() - - m, ok := c.sentRequests.regionReqs[req.regionInfo.subscribedSpan.subID] - - if !ok { - m = make(map[uint64]regionReq) - c.sentRequests.regionReqs[req.regionInfo.subscribedSpan.subID] = m - } - - if oldReq, exists := m[req.regionInfo.verID.GetID()]; exists { - log.Warn("region request overwritten", - zap.Uint64("subID", uint64(req.regionInfo.subscribedSpan.subID)), - zap.Uint64("regionID", req.regionInfo.verID.GetID()), - zap.Float64("oldAgeSec", time.Since(oldReq.createTime).Seconds()), - zap.Float64("newAgeSec", time.Since(req.createTime).Seconds()), - zap.Int("pendingCount", int(c.pendingCount.Load())), - zap.Int("pendingQueueLen", len(c.pendingQueue))) - c.markDone() - } - m[req.regionInfo.verID.GetID()] = req -} - -// markStopped removes a sent request and releases a slot. -func (c *requestCache) markStopped(subID SubscriptionID, regionID uint64) { - c.sentRequests.Lock() - defer c.sentRequests.Unlock() - - regionReqs, ok := c.sentRequests.regionReqs[subID] - if !ok { - return - } - - _, exists := regionReqs[regionID] - if !exists { - return - } - - delete(regionReqs, regionID) - if len(regionReqs) == 0 { - delete(c.sentRequests.regionReqs, subID) - } - c.markDone() -} - -// resolve marks a region as initialized and removes it from sent requests -func (c *requestCache) resolve(subscriptionID SubscriptionID, regionID uint64) bool { - c.sentRequests.Lock() - defer c.sentRequests.Unlock() - regionReqs, ok := c.sentRequests.regionReqs[subscriptionID] - if !ok { - return false - } - - req, exists := regionReqs[regionID] - if !exists { - return false - } - - // Check if the subscription ID matches - if req.regionInfo.subscribedSpan.subID == subscriptionID { - delete(regionReqs, regionID) - c.markDone() - cost := time.Since(req.createTime).Seconds() - if cost > 0 && cost < abnormalRequestDurationInSec { - log.Debug("cdc resolve region request", zap.Uint64("subID", uint64(subscriptionID)), zap.Uint64("regionID", regionID), zap.Float64("cost", cost), zap.Int("pendingCount", int(c.pendingCount.Load())), zap.Int("pendingQueueLen", len(c.pendingQueue))) - metrics.RegionRequestFinishScanDuration.Observe(cost) - } else { - log.Info("region request duration abnormal, skip metric", zap.Float64("cost", cost), zap.Uint64("regionID", regionID)) - } - return true - } - - return false -} - -// clearStaleRequest clears stale requests from the cache -// Note: Sometimes, the CDC sends the same region request to TiKV multiple times. In such cases, this method is needed to reduce the pendingSize. -func (c *requestCache) clearStaleRequest() { - if time.Since(c.lastCheckStaleRequestTime.Load()) < checkStaleRequestInterval { - return - } - c.sentRequests.Lock() - defer c.sentRequests.Unlock() - reqCount := 0 - for subID, regionReqs := range c.sentRequests.regionReqs { - for regionID, regionReq := range regionReqs { - if regionReq.regionInfo.isStopped() || - regionReq.regionInfo.subscribedSpan.stopped.Load() || - regionReq.regionInfo.lockedRangeState.Initialized.Load() || - regionReq.isStale() { - c.markDone() - log.Warn("region worker delete stale region request", - zap.Uint64("subID", uint64(subID)), - zap.Uint64("regionID", regionID), - zap.Int("pendingCount", int(c.pendingCount.Load())), - zap.Int("pendingQueueLen", len(c.pendingQueue)), - zap.Bool("isRegionStopped", regionReq.regionInfo.isStopped()), - zap.Bool("isSubscribedSpanStopped", regionReq.regionInfo.subscribedSpan.stopped.Load()), - zap.Bool("isStale", regionReq.isStale()), - zap.Time("createTime", regionReq.createTime)) - delete(regionReqs, regionID) - } else { - reqCount++ - } - } - if len(regionReqs) == 0 { - delete(c.sentRequests.regionReqs, subID) - } - } - - // If there are no in-cache region requests but pendingCount isn't 0, it means pendingCount is stale. - // Reset it to avoid blocking add() forever. - if reqCount == 0 && len(c.pendingQueue) == 0 && c.pendingCount.Load() != 0 { - log.Info("region worker pending request count is not equal to actual region request count, correct it", - zap.Int("pendingCount", int(c.pendingCount.Load())), - zap.Int("actualReqCount", reqCount), - zap.Int("pendingQueueLen", len(c.pendingQueue))) - c.pendingCount.Store(0) - // Notify waiting add operations that there's space available. - select { - case c.spaceAvailable <- struct{}{}: - default: - } - } - - c.lastCheckStaleRequestTime.Store(time.Now()) -} - -// clear removes all requests and returns them -func (c *requestCache) clear() []regionInfo { - var regions []regionInfo - - // Drain pending requests from channel -LOOP: - for { - select { - case req := <-c.pendingQueue: - regions = append(regions, req.regionInfo) - c.markDone() - default: - break LOOP - } - } - - c.sentRequests.Lock() - defer c.sentRequests.Unlock() - - for subID, regionReqs := range c.sentRequests.regionReqs { - for regionID := range regionReqs { - regions = append(regions, regionReqs[regionID].regionInfo) - delete(regionReqs, regionID) - c.markDone() - } - delete(c.sentRequests.regionReqs, subID) - } - return regions -} - -// getPendingCount returns the current pending count -func (c *requestCache) getPendingCount() int { - return int(c.pendingCount.Load()) -} - -func (c *requestCache) markDone() { - // Decrement pendingCount by 1, but never let it go below 0. - // Do it with CAS to avoid clobbering concurrent Inc() calls. - for { - old := c.pendingCount.Load() - if old == 0 { - break - } else if old < 0 { - if c.pendingCount.CompareAndSwap(old, 0) { - break - } - } else { - if c.pendingCount.CompareAndSwap(old, old-1) { - break - } - } - } - // Notify waiting add operations that there's space available. - select { - case c.spaceAvailable <- struct{}{}: - default: // If channel is full, skip notification - } -} diff --git a/logservice/logpuller/region_request_cache.go b/logservice/logpuller/region_request_cache.go new file mode 100644 index 0000000000..535d01408d --- /dev/null +++ b/logservice/logpuller/region_request_cache.go @@ -0,0 +1,320 @@ +// Copyright 2025 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "context" + "sync" + "time" + + "github.com/pingcap/log" + "github.com/pingcap/ticdc/pkg/metrics" + "github.com/pingcap/ticdc/utils/notifyqueue" + "go.uber.org/zap" +) + +const ( + addReqRetryInterval = time.Millisecond * 1 + addReqRetryLimit = 3 + abnormalRequestDurationInSec = 60 * 60 * 2 // 2 hours +) + +type regionReqStage uint8 + +const ( + // regionReqStageQueued means the request has been admitted but not yet + // picked up by the worker send loop. + regionReqStageQueued regionReqStage = iota + // regionReqStageProcessing means the send loop has popped the request, but + // it has not been recorded as sent yet. + regionReqStageProcessing + // regionReqStageSent means the request has been sent to TiKV and is waiting + // for initialized/resolved/stopped cleanup. + regionReqStageSent +) + +// regionReq tracks one region request from admission to cleanup. +// +// The request also owns the region scan quota. The quota is released when the +// scan is initialized or the request is aborted before scan initialization. +type regionReq struct { + regionInfo regionInfo + createTime time.Time + + // quota is acquired before the request enters requestCache and released + // when the request leaves the worker window. + quota *regionRequestQuota + + // stage is guarded by requestCache.mu. + stage regionReqStage +} + +func newRegionReq(region regionInfo, quota *regionRequestQuota) *regionReq { + return ®ionReq{ + regionInfo: region, + createTime: time.Now(), + quota: quota, + stage: regionReqStageQueued, + } +} + +// requestCache manages worker-local region requests with flow control. +// +// requests is the source of truth for live requests. A request is inserted by +// add(), moves through queued/processing/sent, and is removed by finishScan(), +// abortScan(), drainUnsentRegions(), or close(). +type requestCache struct { + mu sync.Mutex + + // maxPendingCount limits len(requests) for non-force adds. force adds bypass + // this limit, matching the old force behavior for high-priority data requests. + maxPendingCount int + + // requests owns every live region request in this worker. Its length is the + // flow-control count used by add(), pendingCount(), and metrics. + requests map[*regionReq]struct{} + + // queue stores queued requests in FIFO order. + queue *notifyqueue.Queue[*regionReq] + + // spaceAvailable wakes add() when a live request leaves requests. + spaceAvailable chan struct{} + + // onSpaceAvailable lets the store-level deferred scheduler retry a task when + // this worker frees request capacity. + onSpaceAvailable func() +} + +func newRequestCache(maxPendingCount int, onSpaceAvailable func()) *requestCache { + return &requestCache{ + maxPendingCount: maxPendingCount, + requests: make(map[*regionReq]struct{}), + queue: notifyqueue.New[*regionReq](), + spaceAvailable: make(chan struct{}, 1), + onSpaceAvailable: onSpaceAvailable, + } +} + +// add admits a region request into the worker window. +func (c *requestCache) add( + ctx context.Context, region regionInfo, force bool, quota *regionRequestQuota, +) (bool, error) { + start := time.Now() + ticker := time.NewTicker(addReqRetryInterval) + defer ticker.Stop() + retries := addReqRetryLimit + + for { + if c.tryAdd(region, force, quota) { + metrics.SubscriptionClientAddRegionRequestDuration.Observe(time.Since(start).Seconds()) + return true, nil + } + + select { + case <-ticker.C: + retries-- + if retries <= 0 { + return false, nil + } + case <-c.spaceAvailable: + case <-ctx.Done(): + return false, ctx.Err() + } + } +} + +func (c *requestCache) tryAdd(region regionInfo, force bool, quota *regionRequestQuota) bool { + c.mu.Lock() + defer c.mu.Unlock() + + if len(c.requests) >= c.maxPendingCount && !force { + return false + } + + req := newRegionReq(region, quota) + c.requests[req] = struct{}{} + c.queue.Push(req) + return true +} + +// pop takes the next queued request and moves it into processing state. +func (c *requestCache) pop(ctx context.Context) (*regionReq, error) { + for { + if req := c.tryPop(); req != nil { + return req, nil + } + + select { + case <-c.queue.Ready(): + case <-ctx.Done(): + return nil, ctx.Err() + } + } +} + +func (c *requestCache) tryPop() *regionReq { + c.mu.Lock() + defer c.mu.Unlock() + + for { + req, ok := c.queue.TryPop() + if !ok { + return nil + } + if _, ok := c.requests[req]; !ok { + log.Warn("request cache pops a removed request", + zap.Uint64("subID", uint64(req.regionInfo.subscribedSpan.subID)), + zap.Uint64("regionID", req.regionInfo.verID.GetID()), + zap.Uint8("stage", uint8(req.stage))) + continue + } + if req.stage != regionReqStageQueued { + log.Warn("request cache pops a non-queued request", + zap.Uint64("subID", uint64(req.regionInfo.subscribedSpan.subID)), + zap.Uint64("regionID", req.regionInfo.verID.GetID()), + zap.Uint8("stage", uint8(req.stage))) + continue + } + req.stage = regionReqStageProcessing + return req + } +} + +func (c *requestCache) markSent(req *regionReq) { + c.mu.Lock() + defer c.mu.Unlock() + if _, ok := c.requests[req]; ok && req.stage == regionReqStageProcessing { + req.stage = regionReqStageSent + } +} + +func (c *requestCache) finishScan(req *regionReq) bool { + if !c.remove(req) { + return false + } + + cost := time.Since(req.createTime).Seconds() + if cost > 0 && cost < abnormalRequestDurationInSec { + log.Debug("cdc resolve region request", + zap.Uint64("subID", uint64(req.regionInfo.subscribedSpan.subID)), + zap.Uint64("regionID", req.regionInfo.verID.GetID()), + zap.Float64("cost", cost), + zap.Int("pendingCount", c.pendingCount())) + metrics.RegionRequestFinishScanDuration.Observe(cost) + return true + } + log.Info("region request duration abnormal, skip metric", + zap.Float64("cost", cost), + zap.Uint64("regionID", req.regionInfo.verID.GetID())) + return true +} + +func (c *requestCache) abortScan(req *regionReq) bool { + return c.remove(req) +} + +func (c *requestCache) remove(req *regionReq) bool { + if req == nil { + return false + } + + c.mu.Lock() + removed := c.removeLocked(req) + c.mu.Unlock() + + if removed { + req.quota.Release() + c.notifySpace() + } + return removed +} + +// drainUnsentRegions removes queued and processing requests and returns their +// regions. Sent requests are owned by regionTracker and are not drained here. +func (c *requestCache) drainUnsentRegions() []regionInfo { + c.mu.Lock() + removedReqs := make([]*regionReq, 0, len(c.requests)) + regions := make([]regionInfo, 0, len(c.requests)) + for req := range c.requests { + if req.stage == regionReqStageSent { + continue + } + if c.removeLocked(req) { + removedReqs = append(removedReqs, req) + regions = append(regions, req.regionInfo) + } + } + c.queue.Drain() + c.mu.Unlock() + + c.releaseRemovedReqs(removedReqs) + return regions +} + +// close removes all live requests when the worker is closed. +func (c *requestCache) close() { + c.mu.Lock() + removedReqs := make([]*regionReq, 0, len(c.requests)) + for req := range c.requests { + if c.removeLocked(req) { + removedReqs = append(removedReqs, req) + } + } + c.queue.Drain() + c.mu.Unlock() + + c.releaseRemovedReqs(removedReqs) +} + +func (c *requestCache) releaseRemovedReqs(removedReqs []*regionReq) { + if len(removedReqs) > 0 { + for _, req := range removedReqs { + req.quota.Release() + } + c.notifySpace() + } +} + +// pendingCount returns the number of queued, processing and sent requests. +func (c *requestCache) pendingCount() int { + c.mu.Lock() + defer c.mu.Unlock() + return len(c.requests) +} + +func (c *requestCache) removeLocked(req *regionReq) bool { + if req == nil { + return false + } + if _, ok := c.requests[req]; !ok { + return false + } + + delete(c.requests, req) + return true +} + +func (c *requestCache) ready() <-chan struct{} { + return c.queue.Ready() +} + +func (c *requestCache) notifySpace() { + select { + case c.spaceAvailable <- struct{}{}: + default: + } + if c.onSpaceAvailable != nil { + c.onSpaceAvailable() + } +} diff --git a/logservice/logpuller/region_req_cache_test.go b/logservice/logpuller/region_request_cache_test.go similarity index 50% rename from logservice/logpuller/region_req_cache_test.go rename to logservice/logpuller/region_request_cache_test.go index 62706a8542..c600fe8566 100644 --- a/logservice/logpuller/region_req_cache_test.go +++ b/logservice/logpuller/region_request_cache_test.go @@ -15,6 +15,7 @@ package logpuller import ( "context" + "sync/atomic" "testing" "time" @@ -41,16 +42,20 @@ func createTestRegionInfo(subID SubscriptionID, regionID uint64) regionInfo { return newRegionInfo(verID, span, nil, subscribedSpan, false) } +func testRegionRequestQuota() *regionRequestQuota { + return ®ionRequestQuota{release: func() {}} +} + func TestRequestCacheAdd_NormalCase(t *testing.T) { - cache := newRequestCache(10) + cache := newRequestCache(10, nil) ctx := context.Background() region := createTestRegionInfo(1, 1) - ok, err := cache.add(ctx, region, false) + ok, err := cache.add(ctx, region, false, testRegionRequestQuota()) require.NoError(t, err) require.True(t, ok) - require.Equal(t, 1, cache.getPendingCount()) + require.Equal(t, 1, cache.pendingCount()) // Verify the request was added to the queue req, err := cache.pop(ctx) @@ -61,56 +66,49 @@ func TestRequestCacheAdd_NormalCase(t *testing.T) { } func TestRequestCacheAdd_ForceFlag(t *testing.T) { - cache := newRequestCache(1) + cache := newRequestCache(1, nil) ctx := context.Background() // Fill up the cache region1 := createTestRegionInfo(1, 1) - ok, err := cache.add(ctx, region1, false) + ok, err := cache.add(ctx, region1, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) - require.Equal(t, 1, cache.getPendingCount()) + require.Equal(t, 1, cache.pendingCount()) // Try to add another request without force - should fail due to retry limit region2 := createTestRegionInfo(1, 2) - ok, err = cache.add(ctx, region2, false) + ok, err = cache.add(ctx, region2, false, testRegionRequestQuota()) require.False(t, ok) require.NoError(t, err) - // With force=true, it should still fail because the channel is full - // The force flag only bypasses the pendingCount check, not the channel capacity + // With force=true, the request bypasses the live request limit. region3 := createTestRegionInfo(1, 3) - ok, err = cache.add(ctx, region3, true) - require.False(t, ok) + ok, err = cache.add(ctx, region3, true, testRegionRequestQuota()) + require.True(t, ok) require.NoError(t, err) + require.Equal(t, 2, cache.pendingCount()) - // consume the pending queue ann add with force req, err := cache.pop(ctx) require.NoError(t, err) require.NotNil(t, req) require.Equal(t, region1.verID.GetID(), req.regionInfo.verID.GetID()) require.Equal(t, region1.subscribedSpan.subID, req.regionInfo.subscribedSpan.subID) + require.Equal(t, 2, cache.pendingCount()) cache.markSent(req) - require.Equal(t, 1, cache.getPendingCount()) - - ok, err = cache.add(ctx, region3, true) - require.True(t, ok) - require.NoError(t, err) - // It is 2 since region1 is unresolved - require.Equal(t, 2, cache.getPendingCount()) // resolve region1 - cache.resolve(region1.subscribedSpan.subID, region1.verID.GetID()) - require.Equal(t, 1, cache.getPendingCount()) + cache.finishScan(req) + require.Equal(t, 1, cache.pendingCount()) } func TestRequestCacheAdd_ContextCancellation(t *testing.T) { - cache := newRequestCache(1) + cache := newRequestCache(1, nil) // Fill up the cache region1 := createTestRegionInfo(1, 1) ctx1 := context.Background() - ok, err := cache.add(ctx1, region1, false) + ok, err := cache.add(ctx1, region1, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) @@ -119,80 +117,79 @@ func TestRequestCacheAdd_ContextCancellation(t *testing.T) { cancel() // Cancel immediately region2 := createTestRegionInfo(1, 2) - ok, err = cache.add(ctx2, region2, false) + ok, err = cache.add(ctx2, region2, false, testRegionRequestQuota()) require.False(t, ok) require.Error(t, err) require.Equal(t, context.Canceled, err) } func TestRequestCacheAdd_RetryLimitExceeded(t *testing.T) { - cache := newRequestCache(1) + cache := newRequestCache(1, nil) ctx := context.Background() // Fill up the cache region1 := createTestRegionInfo(1, 1) - ok, err := cache.add(ctx, region1, false) + ok, err := cache.add(ctx, region1, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) // Try to add another request - should eventually hit retry limit region2 := createTestRegionInfo(1, 2) - ok, err = cache.add(ctx, region2, false) + ok, err = cache.add(ctx, region2, false, testRegionRequestQuota()) require.False(t, ok) require.NoError(t, err) } func TestRequestCacheAdd_SpaceAvailableNotification(t *testing.T) { - cache := newRequestCache(2) + cache := newRequestCache(2, nil) ctx := context.Background() // Fill up the cache region1 := createTestRegionInfo(1, 1) - ok, err := cache.add(ctx, region1, false) + ok, err := cache.add(ctx, region1, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) - require.Equal(t, 1, cache.getPendingCount()) + require.Equal(t, 1, cache.pendingCount()) region2 := createTestRegionInfo(1, 2) - ok, err = cache.add(ctx, region2, false) + ok, err = cache.add(ctx, region2, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) - require.Equal(t, 2, cache.getPendingCount()) + require.Equal(t, 2, cache.pendingCount()) // Pop a request and mark it as sent, then resolve it to free up space req, err := cache.pop(ctx) require.NoError(t, err) require.NotNil(t, req) - require.Equal(t, 2, cache.getPendingCount()) // pop doesn't change pendingCount - // Mark as sent + require.Equal(t, 2, cache.pendingCount()) // pop doesn't change pendingCount cache.markSent(req) - require.Equal(t, 2, cache.getPendingCount()) + require.Equal(t, 2, cache.pendingCount()) // Resolve the request to free up space - success := cache.resolve(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) + success := cache.finishScan(req) require.True(t, success) - require.Equal(t, 1, cache.getPendingCount()) + require.Equal(t, 1, cache.pendingCount()) // Now we should be able to add another request region3 := createTestRegionInfo(1, 3) - ok, err = cache.add(ctx, region3, false) + ok, err = cache.add(ctx, region3, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) - require.Equal(t, 2, cache.getPendingCount()) + require.Equal(t, 2, cache.pendingCount()) } func TestRequestCacheAdd_ConcurrentAdds(t *testing.T) { - cache := newRequestCache(10) + cache := newRequestCache(10, nil) ctx := context.Background() const numGoroutines = 5 done := make(chan error, numGoroutines) // Start multiple goroutines adding requests concurrently - for i := 0; i < numGoroutines; i++ { + for i := range numGoroutines { go func(id int) { region := createTestRegionInfo(SubscriptionID(id%3), uint64(id)) - ok, err := cache.add(ctx, region, false) + ok, err := cache.add(ctx, region, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) done <- err @@ -200,7 +197,7 @@ func TestRequestCacheAdd_ConcurrentAdds(t *testing.T) { } // Wait for all goroutines to complete - for i := 0; i < numGoroutines; i++ { + for range numGoroutines { select { case err := <-done: require.NoError(t, err) @@ -209,128 +206,88 @@ func TestRequestCacheAdd_ConcurrentAdds(t *testing.T) { } } - require.Equal(t, numGoroutines, cache.getPendingCount()) + require.Equal(t, numGoroutines, cache.pendingCount()) } -func TestRequestCacheAdd_StaleRequestCleanup(t *testing.T) { - cache := newRequestCache(10) +func TestRequestCacheAdd_DuplicateQueuedRequestsAreTrackedIndependently(t *testing.T) { + cache := newRequestCache(10, nil) ctx := context.Background() - // Add a request and mark it as sent region := createTestRegionInfo(1, 1) - ok, err := cache.add(ctx, region, false) + + ok, err := cache.add(ctx, region, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) - req, err := cache.pop(ctx) + ok, err = cache.add(ctx, region, false, testRegionRequestQuota()) + require.True(t, ok) require.NoError(t, err) - require.NotNil(t, req) + require.Equal(t, 2, cache.pendingCount()) - // Mark as sent - cache.markSent(req) - require.Equal(t, 1, cache.getPendingCount()) - - // Manually set the request as stale by modifying createTime - cache.sentRequests.Lock() - regionReqs := cache.sentRequests.regionReqs[req.regionInfo.subscribedSpan.subID] - regionReqs[req.regionInfo.verID.GetID()] = regionReq{ - regionInfo: req.regionInfo, - createTime: time.Now().Add(-requestGCLifeTime - time.Second), // Make it stale - } - cache.sentRequests.Unlock() - - // Manually set lastCheckStaleRequestTime to bypass the time interval check - cache.lastCheckStaleRequestTime.Store(time.Now().Add(-checkStaleRequestInterval - time.Second)) - - // Manually trigger stale cleanup by calling clearStaleRequest - cache.clearStaleRequest() - - // The stale request should be cleaned up - require.Equal(t, 0, cache.getPendingCount()) + req1, err := cache.pop(ctx) + require.NoError(t, err) + req2, err := cache.pop(ctx) + require.NoError(t, err) + require.NotSame(t, req1, req2) } -func TestRequestCacheAdd_WithStoppedRegion(t *testing.T) { - cache := newRequestCache(10) +func TestRequestCacheAbortReleasesSlot(t *testing.T) { + cache := newRequestCache(10, nil) ctx := context.Background() - // Create a region info with stopped state (lockedRangeState = nil) region := createTestRegionInfo(1, 1) - region.lockedRangeState = nil // This makes it stopped - ok, err := cache.add(ctx, region, false) + ok, err := cache.add(ctx, region, false, testRegionRequestQuota()) require.True(t, ok) require.NoError(t, err) - require.Equal(t, 1, cache.getPendingCount()) + require.Equal(t, 1, cache.pendingCount()) req, err := cache.pop(ctx) require.NoError(t, err) - require.NotNil(t, req) - // Mark as sent cache.markSent(req) - require.Equal(t, 1, cache.getPendingCount()) - - // Manually set lastCheckStaleRequestTime to bypass the time interval check - cache.lastCheckStaleRequestTime.Store(time.Now().Add(-checkStaleRequestInterval - time.Second)) + require.Equal(t, 1, cache.pendingCount()) - // Manually trigger cleanup of stopped region - cache.clearStaleRequest() - - // The stopped region should be cleaned up - require.Equal(t, 0, cache.getPendingCount()) + cache.abortScan(req) + require.Equal(t, 0, cache.pendingCount()) } -func TestRequestCacheMarkSent_DuplicateReleaseSlot(t *testing.T) { - cache := newRequestCache(10) +func TestRequestCacheAbortReleasesQuotaOnce(t *testing.T) { + cache := newRequestCache(10, nil) ctx := context.Background() - region := createTestRegionInfo(1, 1) + var releaseCount atomic.Int32 + quota := ®ionRequestQuota{ + release: func() { + releaseCount.Add(1) + }, + } - ok, err := cache.add(ctx, region, false) - require.True(t, ok) - require.NoError(t, err) - - // Add a duplicate request for the same region. It should not leak pendingCount even if - // markSent overwrites the existing entry. - ok, err = cache.add(ctx, region, false) + ok, err := cache.add(ctx, region, false, quota) require.True(t, ok) require.NoError(t, err) - require.Equal(t, 2, cache.getPendingCount()) - req1, err := cache.pop(ctx) - require.NoError(t, err) - cache.markSent(req1) - require.Equal(t, 2, cache.getPendingCount()) - - req2, err := cache.pop(ctx) + req, err := cache.pop(ctx) require.NoError(t, err) - cache.markSent(req2) - require.Equal(t, 1, cache.getPendingCount()) - - // Finish the remaining tracked request. - require.True(t, cache.resolve(region.subscribedSpan.subID, region.verID.GetID())) - require.Equal(t, 0, cache.getPendingCount()) + require.True(t, cache.abortScan(req)) + require.False(t, cache.abortScan(req)) + require.Equal(t, int32(1), releaseCount.Load()) } -func TestRequestCacheMarkStopped_ReleasesSlot(t *testing.T) { - cache := newRequestCache(10) +func TestRequestCacheCloseDrainsQueuedRequests(t *testing.T) { + cache := newRequestCache(10, nil) ctx := context.Background() - region := createTestRegionInfo(1, 1) - - ok, err := cache.add(ctx, region, false) - require.True(t, ok) + ok, err := cache.add(ctx, createTestRegionInfo(1, 1), false, testRegionRequestQuota()) require.NoError(t, err) - require.Equal(t, 1, cache.getPendingCount()) - - req, err := cache.pop(ctx) + require.True(t, ok) + ok, err = cache.add(ctx, createTestRegionInfo(1, 2), false, testRegionRequestQuota()) require.NoError(t, err) + require.True(t, ok) + require.Equal(t, 2, cache.queue.Len()) - cache.markSent(req) - require.Equal(t, 1, cache.getPendingCount()) - require.Contains(t, cache.sentRequests.regionReqs, req.regionInfo.subscribedSpan.subID) - - cache.markStopped(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) - require.Equal(t, 0, cache.getPendingCount()) - require.NotContains(t, cache.sentRequests.regionReqs, req.regionInfo.subscribedSpan.subID) + cache.close() + require.Equal(t, 0, cache.pendingCount()) + require.Equal(t, 0, cache.queue.Len()) + require.Nil(t, cache.tryPop()) } diff --git a/logservice/logpuller/region_request_scheduler.go b/logservice/logpuller/region_request_scheduler.go new file mode 100644 index 0000000000..21c2020fe7 --- /dev/null +++ b/logservice/logpuller/region_request_scheduler.go @@ -0,0 +1,315 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "context" + "strconv" + "sync" + "sync/atomic" + "time" + + "github.com/pingcap/log" + "github.com/pingcap/ticdc/pkg/metrics" + "github.com/pingcap/ticdc/utils/chann" + "github.com/pingcap/ticdc/utils/priorityqueue" + kvclientv2 "github.com/tikv/client-go/v2/kv" + "github.com/tikv/client-go/v2/tikv" + "go.uber.org/zap" + "golang.org/x/sync/errgroup" +) + +const ( + deferReasonStorePending = "store_pending" + deferReasonStoreQuota = "store_quota" + deferReasonWorkerCache = "worker_cache" +) + +// regionRequestScheduler owns region request admission from the global +// priority queue to per-store request workers. +type regionRequestScheduler struct { + config *SubscriptionClientConfig + upstream *upstreamHandle + + eventSink *regionEventSink + failureHandler *regionFailureHandler + + // queue stores newly submitted tasks before they are routed to a TiKV store. + queue *priorityqueue.PriorityQueue[*regionPriorityTask] + // seq is assigned to each task and used as a FIFO tie-breaker when + // multiple tasks have the same priority. + seq atomic.Uint64 + + // schedulerNotify wakes Run to re-check queue or storeAvailable. + schedulerNotify chan struct{} + // storeAvailable is an unbounded ready-store queue. A store is pushed here + // when its quota is released, so deferred tasks for that store can be + // retried without scanning all stores or dropping notifications. + storeAvailable *chann.UnlimitedChannel[*requestedStore, any] + + // stores maps TiKV store address to its scheduler-local state. + stores sync.Map +} + +func newRegionRequestScheduler(client *subscriptionClient) *regionRequestScheduler { + return ®ionRequestScheduler{ + config: client.config, + upstream: client.upstream, + eventSink: client.eventSink, + failureHandler: client.failureHandler, + queue: priorityqueue.New[*regionPriorityTask](), + schedulerNotify: make(chan struct{}, 1), + storeAvailable: chann.NewUnlimitedChannelDefault[*requestedStore](), + } +} + +// Run admits region tasks from two sources: new tasks from the global priority +// queue, and deferred tasks from stores whose quota has become available. +func (s *regionRequestScheduler) Run(ctx context.Context, eg *errgroup.Group) error { + // Store creation is serialized by the single scheduler loop. + getStore := func(storeAddr string) *requestedStore { + var rs *requestedStore + if v, ok := s.stores.Load(storeAddr); ok { + rs = v.(*requestedStore) + return rs + } + + rs = newRequestedStore(s, storeAddr) + s.stores.Store(storeAddr, rs) + rs.Run(ctx, eg) + return rs + } + + for { + select { + case <-ctx.Done(): + return ctx.Err() + default: + } + + // Run is the only consumer of storeAvailable, so Len > 0 means this + // GetWithContext will not block. + if s.storeAvailable.Len() > 0 { + store, ok, err := s.storeAvailable.GetWithContext(context.Background()) + if err != nil || !ok { + continue + } + store.MarkAvailableDequeued() + if err := s.handleDeferredTasks(ctx, store); err != nil { + return err + } + continue + } + + regionTask, ok := s.queue.TryPop() + if ok { + if err := s.handleNewTask(ctx, getStore, regionTask); err != nil { + return err + } + continue + } + + select { + case <-ctx.Done(): + return ctx.Err() + case <-s.schedulerNotify: + } + } +} + +func (s *regionRequestScheduler) Submit(taskType TaskType, region regionInfo) { + task := newRegionPriorityTask(taskType, region, s.upstream.pdClock.CurrentTS(), s.seq.Add(1)) + if s.queue.Push(task) { + s.notifyScheduler() + } +} + +func (s *regionRequestScheduler) BroadcastDeregister(subID SubscriptionID, filterLoop bool) { + s.stores.Range(func(_ any, value any) bool { + rs := value.(*requestedStore) + for _, worker := range rs.requestWorkers { + worker.controlQueue.push(deregisterRequest{ + subID: subID, + filterLoop: filterLoop, + }) + } + return true + }) +} + +func (s *regionRequestScheduler) UpdateMetrics() { + count := 0 + s.stores.Range(func(_, value any) bool { + store := value.(*requestedStore) + quotaUsed, quotaCapacity := store.quota.Snapshot() + metrics.SubscriptionClientStoreDeferredRegionCount.WithLabelValues(store.storeAddr). + Set(float64(store.PendingTaskCount())) + metrics.SubscriptionClientStoreQuotaGauge.WithLabelValues(store.storeAddr, "used"). + Set(float64(quotaUsed)) + metrics.SubscriptionClientStoreQuotaGauge.WithLabelValues(store.storeAddr, "capacity"). + Set(float64(quotaCapacity)) + for _, worker := range store.requestWorkers { + pendingCount := worker.requestCache.pendingCount() + count += pendingCount + metrics.SubscriptionClientWorkerPendingRegionCount.WithLabelValues( + store.storeAddr, + strconv.FormatUint(worker.workerID, 10), + ).Set(float64(pendingCount)) + } + return true + }) + metrics.SubscriptionClientRequestedRegionCount.WithLabelValues("pending"). + Set(float64(count)) +} + +func (s *regionRequestScheduler) Close() { + s.queue.Close() + s.notifyScheduler() + s.stores.Range(func(_, value any) bool { + store := value.(*requestedStore) + store.Close() + return true + }) +} + +func (s *regionRequestScheduler) notifyScheduler() { + select { + case s.schedulerNotify <- struct{}{}: + default: + } +} + +func (s *regionRequestScheduler) attachRPCContextForRegion(ctx context.Context, region regionInfo) (regionInfo, bool) { + bo := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) + rpcCtx, err := s.upstream.regionCache.GetTiKVRPCContext(bo, region.verID, kvclientv2.ReplicaReadLeader, 0) + if rpcCtx != nil { + region.rpcCtx = rpcCtx + return region, true + } + if err != nil { + log.Debug("subscription client get rpc context fail", + zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID)), + zap.Uint64("regionID", region.verID.GetID()), + zap.Error(err)) + } + s.failureHandler.Report(newRegionErrorInfo(region, &rpcCtxUnavailableErr{verID: region.verID})) + return region, false +} + +type getRequestedStoreFunc func(storeAddr string) *requestedStore + +func (s *regionRequestScheduler) handleDeferredTasks(ctx context.Context, store *requestedStore) error { + for { + task, ok := store.TryPopPendingTask() + if !ok { + return nil + } + + region, ok := s.attachRPCContextForRegion(ctx, task.GetRegionInfo()) + if !ok { + continue + } + task.regionInfo = region + + if region.rpcCtx.Addr != store.storeAddr { + s.failureHandler.Report(newRegionErrorInfo(region, &rpcCtxChangedError{ + verID: region.verID, + from: store.storeAddr, + to: region.rpcCtx.Addr, + })) + continue + } + + ok, reason, err := s.tryAdmitTask(ctx, store, task, region) + if err != nil { + return err + } + if !ok { + store.PushPendingTask(task) + s.observeDeferredTask(store, reason) + return nil + } + } +} + +func (s *regionRequestScheduler) handleNewTask( + ctx context.Context, + getStore getRequestedStoreFunc, + task *regionPriorityTask, +) error { + region, ok := s.attachRPCContextForRegion(ctx, task.GetRegionInfo()) + if !ok { + return nil + } + task.regionInfo = region + + store := getStore(region.rpcCtx.Addr) + if store.PendingTaskCount() > 0 { + store.PushPendingTask(task) + store.NotifyAvailable() + s.observeDeferredTask(store, deferReasonStorePending) + return nil + } + + ok, reason, err := s.tryAdmitTask(ctx, store, task, region) + if err != nil { + return err + } + if !ok { + store.PushPendingTask(task) + s.observeDeferredTask(store, reason) + } + return nil +} + +func (s *regionRequestScheduler) tryAdmitTask( + ctx context.Context, + store *requestedStore, + task *regionPriorityTask, + region regionInfo, +) (bool, string, error) { + force := task.Priority() <= forcedPriorityBase + acquiredQuota, ok := store.quota.TryAcquire() + if !ok { + return false, deferReasonStoreQuota, nil + } + ok, worker, err := store.AddRegion(ctx, region, force, acquiredQuota) + if err != nil { + acquiredQuota.Release() + log.Warn("subscription client add region request failed", + zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID)), + zap.Uint64("regionID", region.verID.GetID()), + zap.Error(err)) + return false, "", err + } + if !ok { + acquiredQuota.Release() + return false, deferReasonWorkerCache, nil + } + + metrics.SubscriptionClientRegionRequestAdmitDuration.Observe(time.Since(task.createTime).Seconds()) + log.Debug("subscription client will request a region", + zap.Uint64("workID", worker.workerID), + zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID)), + zap.Uint64("regionID", region.verID.GetID()), + zap.String("addr", store.storeAddr)) + return true, "", nil +} + +func (s *regionRequestScheduler) observeDeferredTask(store *requestedStore, reason string) { + if reason == "" { + return + } + metrics.SubscriptionClientRegionRequestDeferCounter.WithLabelValues(store.storeAddr, reason).Inc() +} diff --git a/logservice/logpuller/region_request_worker.go b/logservice/logpuller/region_request_worker.go index 142f4c6493..747826a875 100644 --- a/logservice/logpuller/region_request_worker.go +++ b/logservice/logpuller/region_request_worker.go @@ -15,6 +15,7 @@ package logpuller import ( "context" + "strconv" "sync" "sync/atomic" "time" @@ -25,163 +26,193 @@ import ( "github.com/pingcap/kvproto/pkg/kvrpcpb" "github.com/pingcap/log" cerror "github.com/pingcap/ticdc/pkg/errors" - "github.com/pingcap/ticdc/pkg/security" + "github.com/pingcap/ticdc/pkg/metrics" "github.com/pingcap/ticdc/pkg/util" "github.com/pingcap/ticdc/pkg/version" + "github.com/pingcap/ticdc/utils/notifyqueue" "go.uber.org/zap" "golang.org/x/sync/errgroup" grpcstatus "google.golang.org/grpc/status" ) +const storeReconnectBackoff = time.Second + // To generate a workerID in `newRegionRequestWorker`. var workerIDGen atomic.Uint64 -type regionFeedStates map[uint64]*regionFeedState +type deregisterRequest struct { + subID SubscriptionID + filterLoop bool +} -// regionRequestWorker is responsible for sending region requests to a specific TiKV store. -type regionRequestWorker struct { - workerID uint64 +type controlQueue struct { + mu sync.Mutex + queue *notifyqueue.Queue[deregisterRequest] +} - client *subscriptionClient +func newControlQueue() *controlQueue { + return &controlQueue{ + queue: notifyqueue.New[deregisterRequest](), + } +} + +func (q *controlQueue) push(req deregisterRequest) { + q.mu.Lock() + defer q.mu.Unlock() + q.queue.Push(req) +} - store *requestedStore +func (q *controlQueue) tryPop() (deregisterRequest, bool) { + q.mu.Lock() + defer q.mu.Unlock() + return q.queue.TryPop() +} + +func (q *controlQueue) len() int { + q.mu.Lock() + defer q.mu.Unlock() + return q.queue.Len() +} + +func (q *controlQueue) ready() <-chan struct{} { + return q.queue.Ready() +} + +// regionRequestWorker is responsible for sending region requests to a specific TiKV store. +type regionRequestWorker struct { + workerID uint64 + storeAddr string - // we must always get a region to request before create a grpc stream. - // only in this way we can avoid to try to connect to an offline store infinitely. - preFetchForConnecting *regionInfo + upstream *upstreamHandle + eventSink *regionEventSink + failureHandler *regionFailureHandler // request cache with flow control requestCache *requestCache + controlQueue *controlQueue - // all regions maintained by this worker. - requestedRegions struct { - sync.RWMutex - - subscriptions map[SubscriptionID]regionFeedStates - } + tracker *regionTracker } func newRegionRequestWorker( - ctx context.Context, - client *subscriptionClient, - credential *security.Credential, - g *errgroup.Group, - store *requestedStore, - requestCacheSize int, + storeAddr string, + requestCache *requestCache, + upstream *upstreamHandle, + eventSink *regionEventSink, + failureHandler *regionFailureHandler, ) *regionRequestWorker { + workerID := workerIDGen.Add(1) worker := ®ionRequestWorker{ - workerID: workerIDGen.Add(1), - client: client, - store: store, - requestCache: newRequestCache(requestCacheSize), + workerID: workerID, + storeAddr: storeAddr, + upstream: upstream, + eventSink: eventSink, + failureHandler: failureHandler, + requestCache: requestCache, + controlQueue: newControlQueue(), + tracker: newRegionTracker(workerID), } - worker.requestedRegions.subscriptions = make(map[SubscriptionID]regionFeedStates) + return worker +} + +func (s *regionRequestWorker) Run(ctx context.Context) error { + for { + // Wait for one data request before connecting, so an idle worker does + // not keep reconnecting to an unavailable store. + firstReq, err := s.waitForRegion(ctx) + if err != nil { + return err + } - waitForPreFetching := func() error { - if worker.preFetchForConnecting != nil { - log.Panic("preFetchForConnecting should be nil", - zap.Uint64("workerID", worker.workerID), - zap.String("addr", store.storeAddr)) + // Run one stream session. A clean stream exit is still treated as a + // store failure so tracked regions can be retried. + var regionErr error = &storeStreamErr{} + if err := s.checkStoreVersion(ctx); err != nil { + regionErr = err + } else if err := s.runStream(ctx, firstReq); err != nil { + regionErr = err } - for { - req, err := worker.requestCache.pop(ctx) - if err != nil { - return err - } - if req.regionInfo.isStopped() { - worker.requestCache.markDone() - continue - } - worker.preFetchForConnecting = new(regionInfo) - *worker.preFetchForConnecting = req.regionInfo - return nil + if ctx.Err() != nil { + return ctx.Err() } - } - g.Go(func() error { - for { - if err := waitForPreFetching(); err != nil { - return err - } - var regionErr error - if err := version.CheckStoreVersion(ctx, worker.client.pd); err != nil { - if errors.Cause(err) == context.Canceled { - return nil - } - log.Error("event feed check store version fails", - zap.Uint64("workerID", worker.workerID), - zap.String("addr", worker.store.storeAddr), - zap.Error(err)) - if cerror.Is(err, cerror.ErrGetAllStoresFailed) { - regionErr = &getStoreErr{} - } else { - regionErr = &storeStreamErr{} - } - } else { - if canceled := worker.run(ctx, credential); canceled { - return nil - } - regionErr = &storeStreamErr{} - } - for subID, m := range worker.clearRegionStates() { - for _, state := range m { - state.markStopped(regionErr) - regionEvent := regionEvent{ - states: []*regionFeedState{state}, - } - worker.client.pushRegionEventToDS(subID, regionEvent) - } - } - // The store may fail forever, so we need try to re-schedule all pending regions. - for _, region := range worker.clearPendingRegions() { - if region.isStopped() { - // It means it's a special task for stopping the table. - continue + // Stop all tracked regions for this stream and send events so the event + // handler can reschedule them through the normal failure path. + for subID, states := range s.tracker.Drain() { + for _, state := range states { + state.markStopped(regionErr) + regionEvent := regionEvent{ + states: []*regionFeedState{state}, } - client.onRegionFail(newRegionErrorInfo(region, regionErr)) - } - if err := util.Hang(ctx, time.Second); err != nil { - return err + s.eventSink.Push(subID, regionEvent) } } - }) + // Unsent regions are not tracked yet, so report them through the + // failure path explicitly. + for _, region := range s.requestCache.drainUnsentRegions() { + s.failureHandler.Report(newRegionErrorInfo(region, regionErr)) + } - return worker + // Avoid a tight reconnect loop when the store keeps failing. + if err := util.Hang(ctx, storeReconnectBackoff); err != nil { + return err + } + } } -func (s *regionRequestWorker) run(ctx context.Context, credential *security.Credential) (canceled bool) { - isCanceled := func() bool { - select { - case <-ctx.Done(): - return true - default: - return false - } +func (s *regionRequestWorker) waitForRegion(ctx context.Context) (*regionReq, error) { + req, err := s.requestCache.pop(ctx) + if err != nil { + return nil, err } + return req, nil +} +func (s *regionRequestWorker) checkStoreVersion(ctx context.Context) error { + err := version.CheckStoreVersion(ctx, s.upstream.pd) + if err == nil { + return nil + } + if ctx.Err() != nil { + return ctx.Err() + } + log.Error("event feed check store version fails", + zap.Uint64("workerID", s.workerID), + zap.String("addr", s.storeAddr), + zap.Error(err)) + if cerror.Is(err, cerror.ErrGetAllStoresFailed) { + return &getStoreErr{} + } + return &storeStreamErr{} +} + +func (s *regionRequestWorker) runStream(ctx context.Context, firstReq *regionReq) (err error) { log.Info("region request worker going to create grpc stream", zap.Uint64("workerID", s.workerID), - zap.String("addr", s.store.storeAddr)) + zap.String("addr", s.storeAddr)) defer func() { log.Info("region request worker exits", zap.Uint64("workerID", s.workerID), - zap.String("addr", s.store.storeAddr), - zap.Bool("canceled", canceled)) + zap.String("addr", s.storeAddr), + zap.Error(err)) }() g, gctx := errgroup.WithContext(ctx) - conn, err := Connect(gctx, credential, s.store.storeAddr) + conn, err := Connect(gctx, s.upstream.credential, s.storeAddr) if err != nil { log.Warn("region request worker create grpc stream failed", zap.Uint64("workerID", s.workerID), - zap.String("addr", s.store.storeAddr), + zap.String("addr", s.storeAddr), zap.Error(err)) // Close the connection if it was partially created to prevent goroutine leaks if conn != nil && conn.Conn != nil { _ = conn.Conn.Close() } - return isCanceled() + if ctx.Err() != nil { + return ctx.Err() + } + return &storeStreamErr{} } defer func() { _ = conn.Conn.Close() @@ -190,7 +221,7 @@ func (s *regionRequestWorker) run(ctx context.Context, credential *security.Cred g.Go(func() error { return s.receiveAndDispatchChangeEvents(conn) }) - g.Go(func() error { return s.processRegionSendTask(gctx, conn) }) + g.Go(func() error { return s.processRegionSendTask(gctx, conn, firstReq) }) failpoint.Inject("InjectForceReconnect", func() { timer := time.After(10 * time.Second) @@ -202,8 +233,14 @@ func (s *regionRequestWorker) run(ctx context.Context, credential *security.Cred }) }) - _ = g.Wait() - return isCanceled() + err = g.Wait() + if err != nil { + if ctx.Err() != nil { + return ctx.Err() + } + return &storeStreamErr{} + } + return nil } func normalizeStreamError(err error) error { @@ -220,7 +257,7 @@ func (s *regionRequestWorker) receiveAndDispatchChangeEvents(conn *ConnAndClient if err != nil { log.Info("region request worker receive from grpc stream failed", zap.Uint64("workerID", s.workerID), - zap.String("addr", s.store.storeAddr), + zap.String("addr", s.storeAddr), zap.String("code", grpcstatus.Code(err).String()), zap.Error(err)) return normalizeStreamError(err) @@ -238,7 +275,7 @@ func (s *regionRequestWorker) dispatchRegionChangeEvents(events []*cdcpb.Event) for _, event := range events { regionID := event.RegionId subscriptionID := SubscriptionID(event.RequestId) - state := s.getRegionState(subscriptionID, regionID) + state := s.tracker.Get(subscriptionID, regionID) if state != nil { regionEvent := regionEvent{ states: []*regionFeedState{state}, @@ -271,7 +308,7 @@ func (s *regionRequestWorker) dispatchRegionChangeEvents(events []*cdcpb.Event) default: log.Panic("unknown event type", zap.Any("event", event)) } - s.client.pushRegionEventToDS(subscriptionID, regionEvent) + s.eventSink.Push(subscriptionID, regionEvent) } else { switch event.Event.(type) { case *cdcpb.Event_Error: @@ -293,7 +330,7 @@ func (s *regionRequestWorker) dispatchRegionChangeEvents(events []*cdcpb.Event) func (s *regionRequestWorker) dispatchResolvedTsEvent(resolvedTsEvent *cdcpb.ResolvedTs) { subscriptionID := SubscriptionID(resolvedTsEvent.RequestId) metricsResolvedTsCount.Add(float64(len(resolvedTsEvent.Regions))) - s.client.metrics.batchResolvedSize.Observe(float64(len(resolvedTsEvent.Regions))) + metrics.BatchResolvedEventSize.WithLabelValues("event-store").Observe(float64(len(resolvedTsEvent.Regions))) // TODO: resolvedTsEvent.Ts be 0 is impossible, we need find the root cause. if resolvedTsEvent.Ts == 0 { log.Warn("region request worker receives a resolved ts event with zero value, ignore it", @@ -314,14 +351,14 @@ func (s *regionRequestWorker) dispatchResolvedTsEvent(resolvedTsEvent *cdcpb.Res if len(resolvedStates) == 0 { return } - s.client.pushRegionEventToDS(subscriptionID, regionEvent{ + s.eventSink.Push(subscriptionID, regionEvent{ resolvedTs: resolvedTsEvent.Ts, states: resolvedStates, }) resolvedStates = nil } for i, regionID := range resolvedTsEvent.Regions { - if state := s.getRegionState(subscriptionID, regionID); state != nil { + if state := s.tracker.Get(subscriptionID, regionID); state != nil { resolvedStates = append(resolvedStates, state) if len(resolvedStates) >= resolvedTsStateBatchSize { flush() @@ -348,6 +385,7 @@ func (s *regionRequestWorker) dispatchResolvedTsEvent(resolvedTsEvent *cdcpb.Res func (s *regionRequestWorker) processRegionSendTask( ctx context.Context, conn *ConnAndClient, + firstReq *regionReq, ) error { doSend := func(req *cdcpb.ChangeDataRequest) error { if err := conn.Client.Send(req); err != nil { @@ -355,91 +393,110 @@ func (s *regionRequestWorker) processRegionSendTask( zap.Uint64("workerID", s.workerID), zap.Uint64("subscriptionID", req.RequestId), zap.Uint64("regionID", req.RegionId), - zap.String("addr", s.store.storeAddr), + zap.String("addr", s.storeAddr), zap.Error(err)) return normalizeStreamError(err) } // TODO: add a metric? return nil } - - // Handle pre-fetched region first - region := *s.preFetchForConnecting - s.preFetchForConnecting = nil - regionReq := newRegionReq(region) - var err error - for { - region := regionReq.regionInfo - subID := region.subscribedSpan.subID - log.Debug("region request worker gets a singleRegionInfo", - zap.Uint64("workerID", s.workerID), - zap.Uint64("subscriptionID", uint64(subID)), - zap.Uint64("regionID", region.verID.GetID()), - zap.String("addr", s.store.storeAddr), - zap.Bool("bdrMode", region.filterLoop)) - - // It means it's a special task for stopping the table. - if region.isStopped() { - req := &cdcpb.ChangeDataRequest{ - Header: &cdcpb.Header{ClusterId: s.client.clusterID, TicdcVersion: version.ReleaseSemver()}, - RequestId: uint64(subID), - Request: &cdcpb.ChangeDataRequest_Deregister_{ - Deregister: &cdcpb.ChangeDataRequest_Deregister{}, - }, - FilterLoop: region.filterLoop, + sendDeregister := func(req deregisterRequest) error { + changeDataReq := &cdcpb.ChangeDataRequest{ + Header: &cdcpb.Header{ClusterId: s.upstream.clusterID, TicdcVersion: version.ReleaseSemver()}, + RequestId: uint64(req.subID), + Request: &cdcpb.ChangeDataRequest_Deregister_{ + Deregister: &cdcpb.ChangeDataRequest_Deregister{}, + }, + FilterLoop: req.filterLoop, + } + if err := doSend(changeDataReq); err != nil { + return err + } + for _, state := range s.tracker.RemoveSubscription(req.subID) { + state.markStopped(&requestCancelledErr{}) + regionEvent := regionEvent{ + states: []*regionFeedState{state}, + } + s.eventSink.Push(req.subID, regionEvent) + } + return nil + } + drainControl := func() error { + for { + req, ok := s.controlQueue.tryPop() + if !ok { + return nil } - s.requestCache.markDone() - if err := doSend(req); err != nil { + if err := sendDeregister(req); err != nil { return err } - for _, state := range s.takeRegionStates(subID) { - state.markStopped(&requestCancelledErr{}) - regionEvent := regionEvent{ - states: []*regionFeedState{state}, + } + } + + regionReq := firstReq + for { + if regionReq != nil { + region := regionReq.regionInfo + subID := region.subscribedSpan.subID + log.Debug("region request worker gets a singleRegionInfo", + zap.Uint64("workerID", s.workerID), + zap.Uint64("subscriptionID", uint64(subID)), + zap.Uint64("regionID", region.verID.GetID()), + zap.String("addr", s.storeAddr), + zap.Bool("bdrMode", region.filterLoop)) + + if region.subscribedSpan.stopped.Load() { + // The subscription has been stopped before this queued request is sent. + s.failureHandler.Report(newRegionErrorInfo(region, &storeStreamErr{})) + s.requestCache.abortScan(regionReq) + } else { + state := newRegionFeedState(region, uint64(subID), s, regionReq) + s.tracker.Track(subID, region.verID.GetID(), state) + // Mark the request as sent before sending it. + // Otherwise there is a race with the receiver goroutine: + // 1. tracker.Track makes the region visible to error handling. + // 2. doSend sends the request. + // 3. the receiver goroutine may receive a region error immediately. + // 4. markStopped runs before markSent, so the request may be finished + // before it is marked as sent. + // 5. the sender goroutine then calls markSent and must not make the + // finished request live again. + // + // Tracking the request before Send keeps regionTracker and + // request lifecycle visible in the same order and avoids leaving stale + // requests behind. + s.requestCache.markSent(regionReq) + if err := doSend(createRegionRequest(s.upstream.clusterID, region)); err != nil { + state.markStopped(err) + return err } - s.client.pushRegionEventToDS(subID, regionEvent) - } - } else if region.subscribedSpan.stopped.Load() { - // It can be skipped directly because there must be no pending states from - // the stopped subscribedTable, or the special singleRegionInfo for stopping - // the table will be handled later. - s.client.onRegionFail(newRegionErrorInfo(region, &storeStreamErr{})) - s.requestCache.markDone() - } else { - state := newRegionFeedState(region, uint64(subID), s) - state.start() - s.addRegionState(subID, region.verID.GetID(), state) - // Mark the request as sent before sending it. - // Otherwise there is a race with the receiver goroutine: - // 1. addRegionState makes the region visible to error handling. - // 2. doSend sends the request. - // 3. the receiver goroutine may receive a region error immediately. - // 4. markStopped runs before markSent, so requestCache.markStopped cannot - // find the request in sentRequests. - // 5. the sender goroutine then calls markSent and leaves a stale sent - // request behind, even though the region has already been - // unlocked/rescheduled. - // - // Tracking the request before Send keeps requestedRegions and - // sentRequests visible in the same order and avoids leaving stale - // requests in cleanup. - s.requestCache.markSent(regionReq) - if err := doSend(s.createRegionRequest(region)); err != nil { - state.markStopped(err) - return err + metrics.SubscriptionClientRegionRequestSendCounter.WithLabelValues( + s.storeAddr, + strconv.FormatUint(s.workerID, 10), + ).Inc() } + regionReq = nil + continue } - // Try to get from cache - regionReq, err = s.requestCache.pop(ctx) - if err != nil { + + if err := drainControl(); err != nil { return err } + if regionReq = s.requestCache.tryPop(); regionReq != nil { + continue + } + select { + case <-s.controlQueue.ready(): + case <-s.requestCache.ready(): + case <-ctx.Done(): + return ctx.Err() + } } } -func (s *regionRequestWorker) createRegionRequest(region regionInfo) *cdcpb.ChangeDataRequest { +func createRegionRequest(clusterID uint64, region regionInfo) *cdcpb.ChangeDataRequest { return &cdcpb.ChangeDataRequest{ - Header: &cdcpb.Header{ClusterId: s.client.clusterID, TicdcVersion: version.ReleaseSemver()}, + Header: &cdcpb.Header{ClusterId: clusterID, TicdcVersion: version.ReleaseSemver()}, RegionId: region.verID.GetID(), RequestId: uint64(region.subscribedSpan.subID), RegionEpoch: region.rpcCtx.Meta.RegionEpoch, @@ -450,79 +507,3 @@ func (s *regionRequestWorker) createRegionRequest(region regionInfo) *cdcpb.Chan FilterLoop: region.filterLoop, } } - -func (s *regionRequestWorker) addRegionState(subscriptionID SubscriptionID, regionID uint64, state *regionFeedState) { - s.requestedRegions.Lock() - defer s.requestedRegions.Unlock() - states := s.requestedRegions.subscriptions[subscriptionID] - if states == nil { - states = make(regionFeedStates) - s.requestedRegions.subscriptions[subscriptionID] = states - } - - states[regionID] = state -} - -func (s *regionRequestWorker) getRegionState(subscriptionID SubscriptionID, regionID uint64) *regionFeedState { - s.requestedRegions.RLock() - defer s.requestedRegions.RUnlock() - if states, ok := s.requestedRegions.subscriptions[subscriptionID]; ok { - return states[regionID] - } - return nil -} - -func (s *regionRequestWorker) takeRegionState(subscriptionID SubscriptionID, regionID uint64) *regionFeedState { - s.requestedRegions.Lock() - defer s.requestedRegions.Unlock() - if statesMap, ok := s.requestedRegions.subscriptions[subscriptionID]; ok { - state := statesMap[regionID] - delete(statesMap, regionID) - if len(statesMap) == 0 { - delete(s.requestedRegions.subscriptions, subscriptionID) - } - return state - } - return nil -} - -func (s *regionRequestWorker) takeRegionStates(subscriptionID SubscriptionID) regionFeedStates { - s.requestedRegions.Lock() - defer s.requestedRegions.Unlock() - states := s.requestedRegions.subscriptions[subscriptionID] - delete(s.requestedRegions.subscriptions, subscriptionID) - return states -} - -func (s *regionRequestWorker) clearRegionStates() map[SubscriptionID]regionFeedStates { - s.requestedRegions.Lock() - defer s.requestedRegions.Unlock() - subscriptions := s.requestedRegions.subscriptions - s.requestedRegions.subscriptions = make(map[SubscriptionID]regionFeedStates) - return subscriptions -} - -// add adds a region request to the worker's cache -// It blocks if the cache is full until there's space or ctx is cancelled -func (s *regionRequestWorker) add(ctx context.Context, region regionInfo, force bool) (bool, error) { - return s.requestCache.add(ctx, region, force) -} - -func (s *regionRequestWorker) clearPendingRegions() []regionInfo { - var regions []regionInfo - - // Clear pre-fetched region - if s.preFetchForConnecting != nil { - region := *s.preFetchForConnecting - s.preFetchForConnecting = nil - regions = append(regions, region) - // The pre-fetched region was popped from pendingQueue but hasn't been marked as sent or done yet. - // Release its pendingCount slot to avoid leaking flow control credits on worker failures. - s.requestCache.markDone() - } - - // Clear all regions from cache - cacheRegions := s.requestCache.clear() - regions = append(regions, cacheRegions...) - return regions -} diff --git a/logservice/logpuller/region_request_worker_test.go b/logservice/logpuller/region_request_worker_test.go index f9752a0eb3..7164a372c6 100644 --- a/logservice/logpuller/region_request_worker_test.go +++ b/logservice/logpuller/region_request_worker_test.go @@ -23,7 +23,6 @@ import ( "github.com/pingcap/kvproto/pkg/metapb" "github.com/pingcap/ticdc/logservice/logpuller/regionlock" "github.com/pingcap/ticdc/utils/dynstream" - "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/require" "github.com/tikv/client-go/v2/tikv" "google.golang.org/grpc" @@ -58,48 +57,101 @@ func prepareRegionForSendTest(region regionInfo) regionInfo { } func TestRegionStatesOperation(t *testing.T) { - worker := ®ionRequestWorker{} - worker.requestedRegions.subscriptions = make(map[SubscriptionID]regionFeedStates) - - require.Nil(t, worker.getRegionState(1, 2)) - require.Nil(t, worker.takeRegionState(1, 2)) - - worker.addRegionState(1, 2, ®ionFeedState{}) - require.NotNil(t, worker.getRegionState(1, 2)) - require.NotNil(t, worker.takeRegionState(1, 2)) - require.Nil(t, worker.getRegionState(1, 2)) - require.Equal(t, 0, len(worker.requestedRegions.subscriptions)) - - worker.addRegionState(1, 2, ®ionFeedState{}) - require.NotNil(t, worker.getRegionState(1, 2)) - require.NotNil(t, worker.takeRegionState(1, 2)) - require.Nil(t, worker.getRegionState(1, 2)) - require.Equal(t, 0, len(worker.requestedRegions.subscriptions)) + tracker := newRegionTracker(0) + + require.Nil(t, tracker.Get(1, 2)) + require.Nil(t, tracker.RemoveRegion(1, 2)) + + tracker.Track(1, 2, ®ionFeedState{}) + require.NotNil(t, tracker.Get(1, 2)) + require.NotNil(t, tracker.RemoveRegion(1, 2)) + require.Nil(t, tracker.Get(1, 2)) + + tracker.Track(1, 2, ®ionFeedState{}) + require.NotNil(t, tracker.Get(1, 2)) + require.NotNil(t, tracker.RemoveRegion(1, 2)) + require.Nil(t, tracker.Get(1, 2)) } -func TestClearPendingRegionsReleaseSlotForPreFetchedRegion(t *testing.T) { +func TestAddRegionStateReleasesOverwrittenRequest(t *testing.T) { + requestCache := newRequestCache(10, nil) worker := ®ionRequestWorker{ - requestCache: newRequestCache(10), + requestCache: requestCache, + tracker: newRegionTracker(0), } ctx := context.Background() region := createTestRegionInfo(1, 1) - ok, err := worker.requestCache.add(ctx, region, false) + ok, err := worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) require.NoError(t, err) require.True(t, ok) + req1, err := worker.requestCache.pop(ctx) + require.NoError(t, err) + worker.requestCache.markSent(req1) + state1 := newRegionFeedState(req1.regionInfo, uint64(req1.regionInfo.subscribedSpan.subID), worker, req1) + worker.tracker.Track(req1.regionInfo.subscribedSpan.subID, req1.regionInfo.verID.GetID(), state1) + + ok, err = worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) + require.NoError(t, err) + require.True(t, ok) + require.Equal(t, 2, worker.requestCache.pendingCount()) + req2, err := worker.requestCache.pop(ctx) + require.NoError(t, err) + state2 := newRegionFeedState(req2.regionInfo, uint64(req2.regionInfo.subscribedSpan.subID), worker, req2) + worker.tracker.Track(req2.regionInfo.subscribedSpan.subID, req2.regionInfo.verID.GetID(), state2) + + require.Equal(t, 1, worker.requestCache.pendingCount()) + require.Same(t, state2, worker.tracker.Get(req2.regionInfo.subscribedSpan.subID, req2.regionInfo.verID.GetID())) +} +func TestInitializedRegionStateDetachesRequest(t *testing.T) { + requestCache := newRequestCache(10, nil) + worker := ®ionRequestWorker{ + requestCache: requestCache, + tracker: newRegionTracker(0), + } + + ctx := context.Background() + region := prepareRegionForSendTest(createTestRegionInfo(1, 1)) + + ok, err := worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) + require.NoError(t, err) + require.True(t, ok) req, err := worker.requestCache.pop(ctx) require.NoError(t, err) - require.Equal(t, 1, worker.requestCache.getPendingCount()) + worker.requestCache.markSent(req) + + state := newRegionFeedState(req.regionInfo, uint64(req.regionInfo.subscribedSpan.subID), worker, req) + worker.tracker.Track(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID(), state) + require.Equal(t, 1, worker.requestCache.pendingCount()) + + state.setInitialized() + require.Equal(t, 0, worker.requestCache.pendingCount()) + + state.markStopped(errors.New("region stopped after initialized")) + require.Equal(t, 0, worker.requestCache.pendingCount()) +} + +func TestDrainUnsentRegionsReleaseSlotForProcessingRegion(t *testing.T) { + worker := ®ionRequestWorker{ + requestCache: newRequestCache(10, nil), + } + + ctx := context.Background() + region := createTestRegionInfo(1, 1) - worker.preFetchForConnecting = new(regionInfo) - *worker.preFetchForConnecting = req.regionInfo + ok, err := worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) + require.NoError(t, err) + require.True(t, ok) - regions := worker.clearPendingRegions() + _, err = worker.requestCache.pop(ctx) + require.NoError(t, err) + require.Equal(t, 1, worker.requestCache.pendingCount()) + + regions := worker.requestCache.drainUnsentRegions() require.Len(t, regions, 1) - require.Nil(t, worker.preFetchForConnecting) - require.Equal(t, 0, worker.requestCache.getPendingCount()) + require.Equal(t, 0, worker.requestCache.pendingCount()) } type pushedResolvedEvent struct { @@ -153,23 +205,14 @@ func (m *mockRegionEventDynamicStream) GetMetrics() dynstream.Metrics[int, Subsc func newDispatchResolvedTsTestWorker(regionCount int) (*regionRequestWorker, *mockRegionEventDynamicStream, *cdcpb.ResolvedTs) { ds := &mockRegionEventDynamicStream{} worker := ®ionRequestWorker{ - client: &subscriptionClient{ - metrics: sharedClientMetrics{ - batchResolvedSize: prometheus.ObserverFunc(func(float64) {}), - }, - ds: ds, - }, - } - worker.requestedRegions.subscriptions = map[SubscriptionID]regionFeedStates{ - 1: make(regionFeedStates, regionCount), + eventSink: ®ionEventSink{ctx: context.Background(), ds: ds}, + tracker: newRegionTracker(0), } regions := make([]uint64, regionCount) for i := 0; i < regionCount; i++ { regionID := uint64(i + 1) regions[i] = regionID - worker.requestedRegions.subscriptions[1][regionID] = ®ionFeedState{ - requestID: 1, - } + worker.tracker.Track(1, regionID, ®ionFeedState{requestID: 1}) } return worker, ds, &cdcpb.ResolvedTs{ @@ -188,14 +231,14 @@ func dispatchResolvedTsEventLegacyForBenchmark(s *regionRequestWorker, resolvedT return } states := resolvedStates - s.client.pushRegionEventToDS(subscriptionID, regionEvent{ + s.eventSink.Push(subscriptionID, regionEvent{ resolvedTs: resolvedTsEvent.Ts, states: states, }) resolvedStates = make([]*regionFeedState, 0, resolvedTsStateBatchSize) } for _, regionID := range resolvedTsEvent.Regions { - if state := s.getRegionState(subscriptionID, regionID); state != nil { + if state := s.tracker.Get(subscriptionID, regionID); state != nil { resolvedStates = append(resolvedStates, state) if len(resolvedStates) >= resolvedTsStateBatchSize { flush() @@ -269,59 +312,60 @@ func BenchmarkDispatchResolvedTsEventSmallBatchCurrent(b *testing.B) { benchmarkDispatchResolvedTsEvent(b, 16, false) } -func TestClearPendingRegionsDoesNotReturnStoppedSentRegion(t *testing.T) { +func TestDrainUnsentRegionsDoesNotReturnStoppedSentRegion(t *testing.T) { + requestCache := newRequestCache(10, nil) worker := ®ionRequestWorker{ - requestCache: newRequestCache(10), + requestCache: requestCache, + tracker: newRegionTracker(0), } - worker.requestedRegions.subscriptions = make(map[SubscriptionID]regionFeedStates) ctx := context.Background() region := createTestRegionInfo(1, 1) - ok, err := worker.requestCache.add(ctx, region, false) + ok, err := worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) require.NoError(t, err) require.True(t, ok) req, err := worker.requestCache.pop(ctx) require.NoError(t, err) - state := newRegionFeedState(req.regionInfo, uint64(req.regionInfo.subscribedSpan.subID), worker) - state.start() - worker.addRegionState(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID(), state) + state := newRegionFeedState(req.regionInfo, uint64(req.regionInfo.subscribedSpan.subID), worker, req) + worker.tracker.Track(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID(), state) - // Simulate the race we are fixing in processRegionSendTask: - // once a request is visible in sentRequests, a fast region error may mark the - // region stopped before worker cleanup runs. In that case, markStopped should - // remove the sent request immediately, so clearPendingRegions must not return - // the stale region again during worker shutdown. + // Simulate the race we are fixing in processRegionSendTask: once a request is + // visible as sent, a fast region error may mark the region stopped before + // worker cleanup runs. In that case, markStopped should abort the request + // immediately, so drainUnsentRegions must not return the stale region again. worker.requestCache.markSent(req) state.markStopped(errors.New("send request to store error")) - worker.takeRegionState(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) + worker.tracker.RemoveRegion(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) - require.Equal(t, 0, worker.requestCache.getPendingCount()) - require.Empty(t, worker.clearPendingRegions()) + require.Equal(t, 0, worker.requestCache.pendingCount()) + require.Empty(t, worker.requestCache.drainUnsentRegions()) } func TestProcessRegionSendTaskSendFailureCleansSentRequest(t *testing.T) { + requestCache := newRequestCache(10, nil) worker := ®ionRequestWorker{ - requestCache: newRequestCache(10), - store: &requestedStore{storeAddr: "store-1"}, - client: &subscriptionClient{}, + requestCache: requestCache, + controlQueue: newControlQueue(), + storeAddr: "store-1", + upstream: &upstreamHandle{}, + eventSink: ®ionEventSink{ctx: context.Background(), ds: &mockRegionEventDynamicStream{}}, + failureHandler: newRegionFailureHandler(&upstreamHandle{}, func(*subscribedSpan) {}, nil, nil), + tracker: newRegionTracker(0), } - worker.requestedRegions.subscriptions = make(map[SubscriptionID]regionFeedStates) ctx := context.Background() region := prepareRegionForSendTest(createTestRegionInfo(1, 1)) - ok, err := worker.requestCache.add(ctx, region, false) + ok, err := worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) require.NoError(t, err) require.True(t, ok) - require.Equal(t, 1, worker.requestCache.getPendingCount()) + require.Equal(t, 1, worker.requestCache.pendingCount()) req, err := worker.requestCache.pop(ctx) require.NoError(t, err) - worker.preFetchForConnecting = new(regionInfo) - *worker.preFetchForConnecting = req.regionInfo sendErr := errors.New("send failed") conn := &ConnAndClient{ @@ -329,11 +373,10 @@ func TestProcessRegionSendTaskSendFailureCleansSentRequest(t *testing.T) { Conn: &grpc.ClientConn{}, } - err = worker.processRegionSendTask(ctx, conn) + err = worker.processRegionSendTask(ctx, conn, req) require.ErrorIs(t, err, sendErr) - require.Equal(t, 0, worker.requestCache.getPendingCount()) - require.Empty(t, worker.requestCache.sentRequests.regionReqs) - state := worker.getRegionState(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) + require.Equal(t, 0, worker.requestCache.pendingCount()) + state := worker.tracker.Get(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) require.True(t, state == nil || state.isStale(), "region state should be removed or marked stale after send failure") } @@ -354,37 +397,38 @@ func TestProcessRegionSendTaskSendEOFIsRetriable(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { + requestCache := newRequestCache(10, nil) worker := ®ionRequestWorker{ - requestCache: newRequestCache(10), - store: &requestedStore{storeAddr: "store-1"}, - client: &subscriptionClient{}, + requestCache: requestCache, + controlQueue: newControlQueue(), + storeAddr: "store-1", + upstream: &upstreamHandle{}, + eventSink: ®ionEventSink{ctx: context.Background(), ds: &mockRegionEventDynamicStream{}}, + failureHandler: newRegionFailureHandler(&upstreamHandle{}, func(*subscribedSpan) {}, nil, nil), + tracker: newRegionTracker(0), } - worker.requestedRegions.subscriptions = make(map[SubscriptionID]regionFeedStates) ctx := context.Background() region := prepareRegionForSendTest(createTestRegionInfo(1, 1)) - ok, err := worker.requestCache.add(ctx, region, false) + ok, err := worker.requestCache.add(ctx, region, false, testRegionRequestQuota()) require.NoError(t, err) require.True(t, ok) req, err := worker.requestCache.pop(ctx) require.NoError(t, err) - worker.preFetchForConnecting = new(regionInfo) - *worker.preFetchForConnecting = req.regionInfo conn := &ConnAndClient{ Client: &mockEventFeedV2Client{sendErr: tc.sendErr}, Conn: &grpc.ClientConn{}, } - err = worker.processRegionSendTask(ctx, conn) + err = worker.processRegionSendTask(ctx, conn, req) var streamErr *storeStreamErr require.ErrorAs(t, err, &streamErr) - require.Equal(t, 0, worker.requestCache.getPendingCount()) - require.Empty(t, worker.requestCache.sentRequests.regionReqs) + require.Equal(t, 0, worker.requestCache.pendingCount()) - state := worker.getRegionState(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) + state := worker.tracker.Get(req.regionInfo.subscribedSpan.subID, req.regionInfo.verID.GetID()) require.NotNil(t, state) require.True(t, state.isStale()) @@ -412,7 +456,7 @@ func TestReceiveAndDispatchChangeEventsEOFIsRetriable(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { worker := ®ionRequestWorker{ - store: &requestedStore{storeAddr: "store-1"}, + storeAddr: "store-1", } conn := &ConnAndClient{ Client: &mockEventFeedV2Client{recvErr: tc.recvErr}, diff --git a/logservice/logpuller/region_state.go b/logservice/logpuller/region_state.go index e9c21a7aad..9043748bdb 100644 --- a/logservice/logpuller/region_state.go +++ b/logservice/logpuller/region_state.go @@ -48,11 +48,6 @@ type regionInfo struct { filterLoop bool } -func (s *regionInfo) isStopped() bool { - // lockedRange only nil when the region's subscribedTable is stopped. - return s.lockedRangeState == nil -} - func newRegionInfo( verID tikv.RegionVerID, span heartbeatpb.TableSpan, @@ -103,19 +98,28 @@ type regionFeedState struct { err error } + regionReq struct { + sync.Mutex + request *regionReq + } + worker *regionRequestWorker } -func newRegionFeedState(region regionInfo, requestID uint64, worker *regionRequestWorker) *regionFeedState { - return ®ionFeedState{ +func newRegionFeedState( + region regionInfo, + requestID uint64, + worker *regionRequestWorker, + request *regionReq, +) *regionFeedState { + state := ®ionFeedState{ region: region, requestID: requestID, + matcher: newMatcher(), worker: worker, } -} - -func (s *regionFeedState) start() { - s.matcher = newMatcher() + state.regionReq.request = request + return state } // mark regionFeedState as stopped with the given error if possible. @@ -126,7 +130,7 @@ func (s *regionFeedState) markStopped(err error) { s.state.v = stateStopped s.state.err = err } - s.worker.requestCache.markStopped(s.region.subscribedSpan.subID, s.region.verID.GetID()) + s.abortScanIfNeeded() } // mark regionFeedState as removed if possible. @@ -138,7 +142,7 @@ func (s *regionFeedState) markRemoved() (changed bool) { changed = true s.matcher.clear() } - s.worker.requestCache.markStopped(s.region.subscribedSpan.subID, s.region.verID.GetID()) + s.abortScanIfNeeded() return } @@ -162,7 +166,27 @@ func (s *regionFeedState) isInitialized() bool { func (s *regionFeedState) setInitialized() { s.region.lockedRangeState.Initialized.Store(true) - s.worker.requestCache.resolve(s.region.subscribedSpan.subID, s.region.verID.GetID()) + s.finishScan() +} + +func (s *regionFeedState) finishScan() { + s.regionReq.Lock() + request := s.regionReq.request + s.regionReq.request = nil + s.regionReq.Unlock() + + s.worker.requestCache.finishScan(request) +} + +func (s *regionFeedState) abortScanIfNeeded() { + s.regionReq.Lock() + request := s.regionReq.request + s.regionReq.request = nil + s.regionReq.Unlock() + + if request != nil { + s.worker.requestCache.abortScan(request) + } } func (s *regionFeedState) getRegionID() uint64 { diff --git a/logservice/logpuller/region_tracker.go b/logservice/logpuller/region_tracker.go new file mode 100644 index 0000000000..07946cbc4d --- /dev/null +++ b/logservice/logpuller/region_tracker.go @@ -0,0 +1,134 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "sync" + + "github.com/pingcap/log" + "go.uber.org/zap" +) + +type trackedRegionStates map[uint64]*regionFeedState + +// regionTracker is the regionRequestWorker-local state registry. +// +// It tracks only the regions sent by one worker. Normal scan request cleanup is +// owned by regionFeedState state transitions, so the tracker only indexes and +// removes states. The overwrite path aborts the old state's scan explicitly +// because no caller will transition that old state afterwards. +type regionTracker struct { + sync.RWMutex + workerID uint64 + + regionsBySubscription map[SubscriptionID]trackedRegionStates +} + +func newRegionTracker(workerID uint64) *regionTracker { + return ®ionTracker{ + workerID: workerID, + regionsBySubscription: make(map[SubscriptionID]trackedRegionStates), + } +} + +// Track records a region after the worker has picked a scan request from +// requestCache and before the request is sent to TiKV. +// +// If the same region is tracked again, the previous state's unfinished scan +// request is aborted before it can leak quota. +func (t *regionTracker) Track(subscriptionID SubscriptionID, regionID uint64, state *regionFeedState) { + t.Lock() + regions := t.regionsBySubscription[subscriptionID] + if regions == nil { + regions = make(trackedRegionStates) + t.regionsBySubscription[subscriptionID] = regions + } + oldState := regions[regionID] + regions[regionID] = state + t.Unlock() + + if oldState == nil { + return + } + log.Warn("region request state overwritten", + zap.Uint64("workerID", t.workerID), + zap.Uint64("subscriptionID", uint64(subscriptionID)), + zap.Uint64("regionID", regionID)) + oldState.abortScanIfNeeded() +} + +// Get returns the tracked region state for events received from TiKV. +// +// A nil return means the event belongs to a stale region, for example after a +// deregister request or stream cleanup. +func (t *regionTracker) Get(subscriptionID SubscriptionID, regionID uint64) *regionFeedState { + t.RLock() + defer t.RUnlock() + + if regions, ok := t.regionsBySubscription[subscriptionID]; ok { + return regions[regionID] + } + return nil +} + +// RemoveRegion removes one tracked region. +func (t *regionTracker) RemoveRegion(subscriptionID SubscriptionID, regionID uint64) *regionFeedState { + t.Lock() + var state *regionFeedState + if regions, ok := t.regionsBySubscription[subscriptionID]; ok { + state = regions[regionID] + delete(regions, regionID) + if len(regions) == 0 { + delete(t.regionsBySubscription, subscriptionID) + } + } + t.Unlock() + return state +} + +// RemoveSubscription removes all tracked regions for a deregistered +// subscription. +func (t *regionTracker) RemoveSubscription(subscriptionID SubscriptionID) []*regionFeedState { + t.Lock() + regions := t.regionsBySubscription[subscriptionID] + delete(t.regionsBySubscription, subscriptionID) + t.Unlock() + + return collectTrackedRegionStates(regions) +} + +// Drain removes all tracked regions when the worker stream is closed. +func (t *regionTracker) Drain() map[SubscriptionID][]*regionFeedState { + t.Lock() + regionsBySubscription := t.regionsBySubscription + t.regionsBySubscription = make(map[SubscriptionID]trackedRegionStates) + t.Unlock() + + statesBySubscription := make(map[SubscriptionID][]*regionFeedState, len(regionsBySubscription)) + for subID, regions := range regionsBySubscription { + statesBySubscription[subID] = collectTrackedRegionStates(regions) + } + return statesBySubscription +} + +func collectTrackedRegionStates(regions trackedRegionStates) []*regionFeedState { + states := make([]*regionFeedState, 0, len(regions)) + for _, state := range regions { + if state == nil { + continue + } + states = append(states, state) + } + return states +} diff --git a/logservice/logpuller/requested_store.go b/logservice/logpuller/requested_store.go new file mode 100644 index 0000000000..11a47a4448 --- /dev/null +++ b/logservice/logpuller/requested_store.go @@ -0,0 +1,200 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "context" + "sync" + "sync/atomic" + + "github.com/pingcap/log" + "github.com/pingcap/ticdc/utils/priorityqueue" + "go.uber.org/zap" + "golang.org/x/sync/errgroup" +) + +type regionRequestQuota struct { + once sync.Once + release func() +} + +func (p *regionRequestQuota) Release() { + p.once.Do(p.release) +} + +type storeQuota struct { + mu sync.Mutex + capacity int + used int + + onRelease func() +} + +func newStoreQuota(capacity int, onRelease func()) *storeQuota { + return &storeQuota{ + capacity: capacity, + onRelease: onRelease, + } +} + +func (q *storeQuota) TryAcquire() (*regionRequestQuota, bool) { + q.mu.Lock() + if q.used >= q.capacity { + q.mu.Unlock() + return nil, false + } + q.used++ + q.mu.Unlock() + + return ®ionRequestQuota{ + release: func() { + q.mu.Lock() + q.used-- + q.mu.Unlock() + if q.onRelease != nil { + q.onRelease() + } + }, + }, true +} + +func (q *storeQuota) Snapshot() (used int, capacity int) { + q.mu.Lock() + defer q.mu.Unlock() + return q.used, q.capacity +} + +// requestedStore is the scheduler's local state for one TiKV store. +type requestedStore struct { + scheduler *regionRequestScheduler + + storeAddr string + quota *storeQuota + // nextWorker is the round-robin cursor used to select the next worker to attempt. + nextWorker atomic.Uint32 + // requestWorkers are fully created before requestedStore is published + // and remain immutable afterwards. + requestWorkers []*regionRequestWorker + + // pendingTasks holds tasks that have been routed to this store but are + // waiting for store quota or worker request-cache capacity. It is mutated + // only by the single regionRequestScheduler.Run loop. + pendingTasks *priorityqueue.PriorityQueue[*regionPriorityTask] + // pendingTaskCount mirrors pendingTasks.Len() for metrics. It lets the + // metrics updater observe the size without touching the scheduler-owned + // priority queue. + pendingTaskCount atomic.Int64 + + notifyMu sync.Mutex + notifyEnqueued bool +} + +func newRequestedStore(scheduler *regionRequestScheduler, storeAddr string) *requestedStore { + pendingRegionRequestQueueSize := scheduler.config.PendingRegionRequestQueueSize + regionRequestWorkerPerStore := scheduler.config.RegionRequestWorkerPerStore + perWorkerQueueSize := pendingRegionRequestQueueSize / int(regionRequestWorkerPerStore) + if perWorkerQueueSize <= 0 { + log.Warn("pending region request queue size is smaller than the number of workers, adjust per worker queue size to 1", + zap.Int("pendingRegionRequestQueueSize", pendingRegionRequestQueueSize), + zap.Uint("regionRequestWorkerPerStore", regionRequestWorkerPerStore)) + perWorkerQueueSize = 1 + } + perStoreQuotaSize := perWorkerQueueSize * int(regionRequestWorkerPerStore) + + rs := &requestedStore{ + scheduler: scheduler, + storeAddr: storeAddr, + requestWorkers: make([]*regionRequestWorker, 0, regionRequestWorkerPerStore), + pendingTasks: priorityqueue.New[*regionPriorityTask](), + } + rs.quota = newStoreQuota(perStoreQuotaSize, rs.NotifyAvailable) + for range regionRequestWorkerPerStore { + requestCache := newRequestCache(perWorkerQueueSize, rs.NotifyAvailable) + requestWorker := newRegionRequestWorker( + storeAddr, + requestCache, + scheduler.upstream, + scheduler.eventSink, + scheduler.failureHandler, + ) + rs.requestWorkers = append(rs.requestWorkers, requestWorker) + } + return rs +} + +func (rs *requestedStore) Run(ctx context.Context, eg *errgroup.Group) { + for _, worker := range rs.requestWorkers { + eg.Go(func() error { + return worker.Run(ctx) + }) + } +} + +func (rs *requestedStore) Close() { + for _, worker := range rs.requestWorkers { + worker.requestCache.close() + } +} + +func (rs *requestedStore) PushPendingTask(task *regionPriorityTask) { + rs.pendingTasks.Push(task) + rs.pendingTaskCount.Add(1) +} + +func (rs *requestedStore) TryPopPendingTask() (*regionPriorityTask, bool) { + task, ok := rs.pendingTasks.TryPop() + if ok { + rs.pendingTaskCount.Add(-1) + } + return task, ok +} + +func (rs *requestedStore) PendingTaskCount() int { + return int(rs.pendingTaskCount.Load()) +} + +func (rs *requestedStore) AddRegion( + ctx context.Context, region regionInfo, force bool, quota *regionRequestQuota, +) (bool, *regionRequestWorker, error) { + workers := rs.requestWorkers + + start := int(rs.nextWorker.Add(1)) % len(workers) + for i := range len(workers) { + worker := workers[(start+i)%len(workers)] + ok, err := worker.requestCache.add(ctx, region, force, quota) + if err != nil || ok { + return ok, worker, err + } + } + return false, nil, nil +} + +func (rs *requestedStore) NotifyAvailable() { + rs.notifyMu.Lock() + if rs.notifyEnqueued { + rs.notifyMu.Unlock() + return + } + rs.notifyEnqueued = true + rs.notifyMu.Unlock() + + rs.scheduler.storeAvailable.Push(rs) + rs.scheduler.notifyScheduler() +} + +func (rs *requestedStore) MarkAvailableDequeued() { + rs.notifyMu.Lock() + rs.notifyEnqueued = false + rs.notifyMu.Unlock() +} diff --git a/logservice/logpuller/span_registry.go b/logservice/logpuller/span_registry.go new file mode 100644 index 0000000000..c4cc080892 --- /dev/null +++ b/logservice/logpuller/span_registry.go @@ -0,0 +1,307 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package logpuller + +import ( + "context" + "sync" + "sync/atomic" + "time" + + "github.com/pingcap/log" + "github.com/pingcap/ticdc/heartbeatpb" + "github.com/pingcap/ticdc/logservice/logpuller/regionlock" + "github.com/pingcap/ticdc/pkg/common" + "github.com/pingcap/ticdc/pkg/metrics" + "github.com/pingcap/ticdc/pkg/util" + "github.com/tikv/client-go/v2/oracle" + "go.uber.org/zap" + "golang.org/x/sync/errgroup" +) + +const kvEventsCacheMaxSize = 32 + +// subscribedSpan is the local state for one subscribed table span. +type subscribedSpan struct { + subID SubscriptionID + startTs uint64 + // Whether to filter out the value written by TiCDC itself. + // It should be `true` in BDR mode. + filterLoop bool + + // The target span. + span heartbeatpb.TableSpan + // The range lock of the span, + // it is used to prevent duplicate requests to the same region range, + // and it also used to calculate this table's resolvedTs. + rangeLock *regionlock.RangeLock + + consumeKVEvents func(events []common.RawKVEntry, wakeCallback func()) bool + + advanceResolvedTs func(ts uint64) + + advanceInterval int64 + + kvEventsCache []common.RawKVEntry + + // To handle span removing. + stopped atomic.Bool + + // To handle stale lock resolvings. + tryResolveLock func(regionID uint64, state *regionlock.LockedRangeState) + staleLocksTargetTs atomic.Uint64 + + lastAdvanceTime atomic.Int64 + + initialized atomic.Bool + resolvedTsUpdated atomic.Int64 + resolvedTs atomic.Uint64 +} + +type spanRegistry struct { + sync.RWMutex + spans map[SubscriptionID]*subscribedSpan + + upstream *upstreamHandle +} + +type spanAndTargetTs struct { + span *subscribedSpan + targetTs uint64 +} + +func newSubscribedSpan( + ctx context.Context, + resolveLockRateLimiter *resolveLockRateLimiter, + resolveLockTaskCh chan resolveLockTask, + subID SubscriptionID, + span heartbeatpb.TableSpan, + startTs uint64, + consumeKVEvents func(raw []common.RawKVEntry, wakeCallback func()) bool, + advanceResolvedTs func(ts uint64), + advanceInterval int64, + filterLoop bool, +) *subscribedSpan { + rangeLock := regionlock.NewRangeLock(uint64(subID), span.StartKey, span.EndKey, startTs) + + rt := &subscribedSpan{ + subID: subID, + span: span, + startTs: startTs, + filterLoop: filterLoop, + rangeLock: rangeLock, + + consumeKVEvents: consumeKVEvents, + advanceResolvedTs: advanceResolvedTs, + advanceInterval: advanceInterval, + } + rt.initialized.Store(false) + rt.resolvedTsUpdated.Store(time.Now().Unix()) + rt.resolvedTs.Store(startTs) + + rt.tryResolveLock = func(regionID uint64, state *regionlock.LockedRangeState) { + targetTs := rt.staleLocksTargetTs.Load() + if !state.Initialized.Load() || state.ResolvedTs.Load() >= targetTs { + return + } + key := resolveLockKey{keyspaceID: span.KeyspaceID, regionID: regionID} + if !resolveLockRateLimiter.trySchedule(key, time.Now()) { + return + } + select { + case <-ctx.Done(): + resolveLockRateLimiter.cancel(key) + case resolveLockTaskCh <- resolveLockTask{ + keyspaceID: span.KeyspaceID, + regionID: regionID, + targetTs: targetTs, + state: state, + }: + // it is ok to ignore resolve lock task when the channel is full + default: + resolveLockRateLimiter.cancel(key) + metrics.SubscriptionClientResolveLockTaskDropCounter.Inc() + } + } + return rt +} + +func (span *subscribedSpan) clearKVEventsCache() { + if cap(span.kvEventsCache) > kvEventsCacheMaxSize { + span.kvEventsCache = nil + } else { + span.kvEventsCache = span.kvEventsCache[:0] + } +} + +func (span *subscribedSpan) resolveStaleLocks(targetTs uint64) { + util.MustCompareAndMonotonicIncrease(&span.staleLocksTargetTs, targetTs) + res := span.rangeLock.IterAll(span.tryResolveLock) + log.Debug("subscription client finds slow locked ranges", + zap.Uint64("subscriptionID", uint64(span.subID)), + zap.Any("ranges", res)) +} + +func newSpanRegistry(upstream *upstreamHandle) *spanRegistry { + return &spanRegistry{ + spans: make(map[SubscriptionID]*subscribedSpan), + upstream: upstream, + } +} + +func (r *spanRegistry) Add(span *subscribedSpan) { + r.Lock() + defer r.Unlock() + r.spans[span.subID] = span +} + +func (r *spanRegistry) Get(subID SubscriptionID) *subscribedSpan { + r.RLock() + defer r.RUnlock() + return r.spans[subID] +} + +func (r *spanRegistry) Remove(subID SubscriptionID) { + r.Lock() + defer r.Unlock() + delete(r.spans, subID) +} + +func (r *spanRegistry) UpdateMetrics() { + count := 0 + pullerMinResolvedTs := uint64(0) + r.RLock() + for _, span := range r.spans { + count += span.rangeLock.Len() + resolvedTs := span.resolvedTs.Load() + if pullerMinResolvedTs == 0 || resolvedTs < pullerMinResolvedTs { + pullerMinResolvedTs = resolvedTs + } + } + r.RUnlock() + metrics.SubscriptionClientSubscribedRegionCount.Set(float64(count)) + + if pullerMinResolvedTs == 0 { + return + } + pdTime := r.upstream.pdClock.CurrentTime() + phyResolvedTs := oracle.ExtractPhysical(pullerMinResolvedTs) + resolvedTsLag := float64(oracle.GetPhysical(pdTime)-phyResolvedTs) / 1e3 + if resolvedTsLag > 0 { + metrics.LogPullerResolvedTsLag.Set(resolvedTsLag) + } +} + +func (r *spanRegistry) Run(ctx context.Context) error { + g, ctx := errgroup.WithContext(ctx) + g.Go(func() error { return r.runResolveLockChecker(ctx) }) + g.Go(func() error { return r.logSlowRegions(ctx) }) + return g.Wait() +} + +func (r *spanRegistry) runResolveLockChecker(ctx context.Context) error { + resolveLockTicker := time.NewTicker(resolveLockTickInterval) + defer resolveLockTicker.Stop() + maxCacheSize := 1024 + spanAndTsCache := make([]spanAndTargetTs, 0, maxCacheSize) + // getResolvedTargetTs returns the targetTs to resolve stale locks. 0 means no need to resolve. + getResolvedTargetTs := func(subSpan *subscribedSpan, currentTime time.Time, currentTs uint64) uint64 { + resolvedTsUpdated := time.Unix(subSpan.resolvedTsUpdated.Load(), 0) + if !subSpan.initialized.Load() || time.Since(resolvedTsUpdated) < resolveLockFence { + return 0 + } + resolvedTs := subSpan.resolvedTs.Load() + resolvedTime := oracle.GetTimeFromTS(resolvedTs) + if currentTime.Sub(resolvedTime) < resolveLockFence { + return 0 + } + return min(currentTs, oracle.GoTimeToTS(resolvedTime.Add(resolveLockFence))) + } + + for { + select { + case <-ctx.Done(): + return ctx.Err() + case <-resolveLockTicker.C: + } + + physical, logic, err := r.upstream.pd.GetTS(ctx) + if err != nil { + log.Warn("get ts from pd failed", zap.Error(err)) + continue + } + currentTs := oracle.ComposeTS(physical, logic) + currentTime := r.upstream.pdClock.CurrentTime() + r.RLock() + for _, subSpan := range r.spans { + if subSpan != nil { + targetTs := getResolvedTargetTs(subSpan, currentTime, currentTs) + if targetTs > 0 { + spanAndTsCache = append(spanAndTsCache, spanAndTargetTs{ + span: subSpan, + targetTs: targetTs, + }) + } + } + } + r.RUnlock() + for _, spanAndTs := range spanAndTsCache { + spanAndTs.span.resolveStaleLocks(spanAndTs.targetTs) + } + spanAndTsCache = spanAndTsCache[:0] + if cap(spanAndTsCache) > maxCacheSize { + spanAndTsCache = make([]spanAndTargetTs, 0, maxCacheSize) + } + } +} + +func (r *spanRegistry) logSlowRegions(ctx context.Context) error { + ticker := time.NewTicker(30 * time.Second) + defer ticker.Stop() + for { + select { + case <-ctx.Done(): + return ctx.Err() + case <-ticker.C: + } + + currTime := r.upstream.pdClock.CurrentTime() + r.RLock() + for subscriptionID, rt := range r.spans { + attr := rt.rangeLock.IterAll(nil) + ckptTime := oracle.GetTimeFromTS(attr.SlowestRegion.ResolvedTs) + if attr.SlowestRegion.Initialized { + if currTime.Sub(ckptTime) > 6*resolveLockMinInterval { + log.Info("subscription client finds a initialized slow region", + zap.Uint64("subscriptionID", uint64(subscriptionID)), + zap.Any("slowRegion", attr.SlowestRegion)) + } + } else if currTime.Sub(attr.SlowestRegion.Created) > 10*time.Minute { + log.Info("subscription client initializes a region too slow", + zap.Uint64("subscriptionID", uint64(subscriptionID)), + zap.Any("slowRegion", attr.SlowestRegion)) + } else if currTime.Sub(ckptTime) > 10*time.Minute { + log.Info("subscription client finds a uninitialized slow region", + zap.Uint64("subscriptionID", uint64(subscriptionID)), + zap.Any("slowRegion", attr.SlowestRegion)) + } + if len(attr.UnLockedRanges) > 0 { + log.Info("subscription client holes exist", + zap.Uint64("subscriptionID", uint64(subscriptionID)), + zap.Any("holes", attr.UnLockedRanges)) + } + } + r.RUnlock() + } +} diff --git a/logservice/logpuller/subscription_client.go b/logservice/logpuller/subscription_client.go index fbcffdc4f1..a5a0ee2b8f 100644 --- a/logservice/logpuller/subscription_client.go +++ b/logservice/logpuller/subscription_client.go @@ -15,7 +15,6 @@ package logpuller import ( "context" - "sync" "sync/atomic" "time" @@ -26,18 +25,11 @@ import ( "github.com/pingcap/ticdc/logservice/txnutil" "github.com/pingcap/ticdc/pkg/common" appcontext "github.com/pingcap/ticdc/pkg/common/context" - "github.com/pingcap/ticdc/pkg/config" - "github.com/pingcap/ticdc/pkg/errors" "github.com/pingcap/ticdc/pkg/metrics" "github.com/pingcap/ticdc/pkg/pdutil" "github.com/pingcap/ticdc/pkg/security" "github.com/pingcap/ticdc/pkg/spanz" "github.com/pingcap/ticdc/pkg/util" - "github.com/pingcap/ticdc/utils/dynstream" - "github.com/pingcap/ticdc/utils/priorityqueue" - "github.com/prometheus/client_golang/prometheus" - kvclientv2 "github.com/tikv/client-go/v2/kv" - "github.com/tikv/client-go/v2/oracle" "github.com/tikv/client-go/v2/tikv" pd "github.com/tikv/pd/client" "go.uber.org/zap" @@ -48,11 +40,6 @@ const ( // Maximum total sleep time(in ms), 20 seconds. tikvRequestMaxBackoff = 20000 - // TiCDC always interacts with region leader, every time something goes wrong, - // failed region will be reloaded via `BatchLoadRegionsWithKeyRange` API. So we - // don't need to force reload region anymore. - regionScheduleReload = false - loadRegionRetryInterval time.Duration = 100 * time.Millisecond resolveLockMinInterval time.Duration = 10 * time.Second resolveLockTickInterval time.Duration = 2 * time.Second @@ -60,18 +47,8 @@ const ( ) var ( - metricFeedNotLeaderCounter = metrics.EventFeedErrorCounter.WithLabelValues("NotLeader") - metricFeedEpochNotMatchCounter = metrics.EventFeedErrorCounter.WithLabelValues("EpochNotMatch") - metricFeedRegionNotFoundCounter = metrics.EventFeedErrorCounter.WithLabelValues("RegionNotFound") - metricFeedDuplicateRequestCounter = metrics.EventFeedErrorCounter.WithLabelValues("DuplicateRequest") - metricFeedUnknownErrorCounter = metrics.EventFeedErrorCounter.WithLabelValues("Unknown") - metricFeedRPCCtxUnavailable = metrics.EventFeedErrorCounter.WithLabelValues("RPCCtxUnavailable") - metricGetStoreErr = metrics.EventFeedErrorCounter.WithLabelValues("GetStoreErr") - metricStoreSendRequestErr = metrics.EventFeedErrorCounter.WithLabelValues("SendRequestToStore") - metricKvIsBusyCounter = metrics.EventFeedErrorCounter.WithLabelValues("KvIsBusy") - metricKvCongestedCounter = metrics.EventFeedErrorCounter.WithLabelValues("KvCongested") - metricResolveLockSuccessCounter = metrics.SubscriptionClientResolveLockCounter.WithLabelValues("success") - metricResolveLockFailureCounter = metrics.SubscriptionClientResolveLockCounter.WithLabelValues("failure") + metricResolveLockSuccessCounter = metrics.SubscriptionClientResolveLockCounter.WithLabelValues("success") + metricResolveLockFailureCounter = metrics.SubscriptionClientResolveLockCounter.WithLabelValues("failure") metricSubscriptionClientDSChannelSize = metrics.DynamicStreamEventChanSize.WithLabelValues("event-store") metricSubscriptionClientDSPendingQueueLen = metrics.DynamicStreamPendingQueueLen.WithLabelValues("event-store") @@ -102,62 +79,23 @@ type rangeTask struct { priority TaskType } -const kvEventsCacheMaxSize = 32 - -// subscribedSpan represents a span to subscribe. -// It contains a sub span of a table(or the total span of a table), -// the startTs of the table, and the output event channel. -type subscribedSpan struct { - subID SubscriptionID - startTs uint64 - // Whether to filter out the value written by TiCDC itself. - // It should be `true` in BDR mode. - filterLoop bool - - // The target span - span heartbeatpb.TableSpan - // The range lock of the span, - // it is used to prevent duplicate requests to the same region range, - // and it also used to calculate this table's resolvedTs. - rangeLock *regionlock.RangeLock - - consumeKVEvents func(events []common.RawKVEntry, wakeCallback func()) bool - - advanceResolvedTs func(ts uint64) - - advanceInterval int64 - - kvEventsCache []common.RawKVEntry - - // To handle span removing. - stopped atomic.Bool - - // To handle stale lock resolvings. - tryResolveLock func(regionID uint64, state *regionlock.LockedRangeState) - staleLocksTargetTs atomic.Uint64 - - lastAdvanceTime atomic.Int64 - - initialized atomic.Bool - resolvedTsUpdated atomic.Int64 - resolvedTs atomic.Uint64 -} - -func (span *subscribedSpan) clearKVEventsCache() { - if cap(span.kvEventsCache) > kvEventsCacheMaxSize { - span.kvEventsCache = nil - } else { - span.kvEventsCache = span.kvEventsCache[:0] - } -} - type SubscriptionClientConfig struct { // The number of region request workers to send region task for every tikv store RegionRequestWorkerPerStore uint + // PendingRegionRequestQueueSize is the total pending region request quota for one TiKV store. + PendingRegionRequestQueueSize int } -type sharedClientMetrics struct { - batchResolvedSize prometheus.Observer +type upstreamHandle struct { + pd pd.Client + credential *security.Credential + pdClock pdutil.Clock + regionCache *tikv.RegionCache + clusterID uint64 +} + +func (u *upstreamHandle) Initialize(ctx context.Context) { + u.clusterID = u.pd.GetClusterID(ctx) } // subscriptionClient is used to subscribe events of table ranges from TiKV. @@ -181,46 +119,26 @@ type SubscriptionClient interface { } type subscriptionClient struct { - ctx context.Context - cancel context.CancelFunc - config *SubscriptionClientConfig - metrics sharedClientMetrics - clusterID uint64 + ctx context.Context + cancel context.CancelFunc + config *SubscriptionClientConfig + upstream *upstreamHandle - pd pd.Client - regionCache *tikv.RegionCache - pdClock pdutil.Clock lockResolver txnutil.LockResolver - stores sync.Map - - ds dynstream.DynamicStream[int, SubscriptionID, regionEvent, *subscribedSpan, *regionEventHandler] - // the following three fields are used to manage feedback from ds and notify other goroutines - mu sync.Mutex - cond *sync.Cond - paused atomic.Bool - - // the credential to connect tikv - credential *security.Credential + eventSink *regionEventSink + failureHandler *regionFailureHandler - totalSpans struct { - sync.RWMutex - spanMap map[SubscriptionID]*subscribedSpan - } + spanRegistry *spanRegistry // rangeTaskCh is used to receive range tasks. // The tasks will be handled in `handleRangeTask` goroutine. - rangeTaskCh chan rangeTask - // regionTaskQueue is used to receive region tasks with priority. - // The region will be handled in `handleRegions` goroutine. - regionTaskQueue *priorityqueue.PriorityQueue[PriorityTask] + rangeTaskCh chan rangeTask + regionScheduler *regionRequestScheduler // resolveLockTaskCh is used to receive resolve lock tasks. // The tasks will be handled in `handleResolveLockTasks` goroutine. resolveLockTaskCh chan resolveLockTask resolveLockRateLimiter *resolveLockRateLimiter - // errCh is used to receive region errors. - // The errors will be handled in `handleErrors` goroutine. - errCache *errCache } // NewSubscriptionClient creates a client. @@ -230,43 +148,33 @@ func NewSubscriptionClient( lockResolver txnutil.LockResolver, credential *security.Credential, ) SubscriptionClient { + regionCache := appcontext.GetService[*tikv.RegionCache](appcontext.RegionCache) + pdClock := appcontext.GetService[pdutil.Clock](appcontext.DefaultPDClock) subClient := &subscriptionClient{ config: config, - - stores: sync.Map{}, - pd: pd, - regionCache: appcontext.GetService[*tikv.RegionCache](appcontext.RegionCache), - pdClock: appcontext.GetService[pdutil.Clock](appcontext.DefaultPDClock), + upstream: &upstreamHandle{ + pd: pd, + credential: credential, + pdClock: pdClock, + regionCache: regionCache, + }, lockResolver: lockResolver, - credential: credential, - rangeTaskCh: make(chan rangeTask, 1024), - regionTaskQueue: priorityqueue.New[PriorityTask](), resolveLockTaskCh: make(chan resolveLockTask, 1024), resolveLockRateLimiter: newResolveLockRateLimiter(), - errCache: newErrCache(), } subClient.ctx, subClient.cancel = context.WithCancel(context.Background()) - subClient.totalSpans.spanMap = make(map[SubscriptionID]*subscribedSpan) + subClient.spanRegistry = newSpanRegistry(subClient.upstream) - option := dynstream.NewOption() - // Note: it is max batch size of the kv sent from tikv(not committed rows) - option.BatchCount = 1024 - // TODO: Set `UseBuffer` to true until we refactor the `regionEventHandler.Handle` method so that it doesn't call any method of the dynamic stream. Currently, if `UseBuffer` is set to false, there will be a deadlock: - // ds.handleLoop fetch events from `ch` -> regionEventHandler.Handle -> ds.RemovePath -> send event to `ch` - option.UseBuffer = true - option.EnableMemoryControl = true - ds := dynstream.NewParallelDynamicStream( - "log-puller", - ®ionEventHandler{subClient: subClient}, - option, + subClient.failureHandler = newRegionFailureHandler( + subClient.upstream, + subClient.onTableDrained, + subClient.scheduleRegionRequest, + subClient.scheduleRangeRequest, ) - ds.Start() - subClient.ds = ds - subClient.cond = sync.NewCond(&subClient.mu) - - subClient.initMetrics() + subClient.eventSink = newRegionEventSink(subClient.ctx, subClient.failureHandler) + subClient.regionScheduler = newRegionRequestScheduler(subClient) return subClient } @@ -279,12 +187,7 @@ func (s *subscriptionClient) AllocSubscriptionID() SubscriptionID { return SubscriptionID(subscriptionIDGen.Add(1)) } -func (s *subscriptionClient) initMetrics() { - // TODO: fix metrics - s.metrics.batchResolvedSize = metrics.BatchResolvedEventSize.WithLabelValues("event-store") -} - -func (s *subscriptionClient) updateMetrics(ctx context.Context) error { +func (s *subscriptionClient) runMetricsUpdater(ctx context.Context) error { ticker := time.NewTicker(10 * time.Second) defer ticker.Stop() for { @@ -292,11 +195,7 @@ func (s *subscriptionClient) updateMetrics(ctx context.Context) error { case <-ctx.Done(): return ctx.Err() case <-ticker.C: - resolvedTsLag := s.GetResolvedTsLag() - if resolvedTsLag > 0 { - metrics.LogPullerResolvedTsLag.Set(resolvedTsLag) - } - dsMetrics := s.ds.GetMetrics() + dsMetrics := s.eventSink.Metrics() metricSubscriptionClientDSChannelSize.Set(float64(dsMetrics.EventChanSize)) metricSubscriptionClientDSPendingQueueLen.Set(float64(dsMetrics.PendingQueueLen)) if len(dsMetrics.MemoryControl.AreaMemoryMetrics) > 1 { @@ -318,34 +217,15 @@ func (s *subscriptionClient) updateMetrics(ctx context.Context) error { ).Set(float64(areaMetric.MemoryUsage())) } - pendingRegionReqCount := 0 - s.stores.Range(func(_, value any) bool { - store := value.(*requestedStore) - store.requestWorkers.RLock() - for _, worker := range store.requestWorkers.s { - worker.requestCache.clearStaleRequest() - pendingRegionReqCount += worker.requestCache.getPendingCount() - } - store.requestWorkers.RUnlock() - return true - }) - - metrics.SubscriptionClientRequestedRegionCount.WithLabelValues("pending").Set(float64(pendingRegionReqCount)) - - count := 0 - s.totalSpans.RLock() - for _, rt := range s.totalSpans.spanMap { - count += rt.rangeLock.Len() - } - s.totalSpans.RUnlock() - metrics.SubscriptionClientSubscribedRegionCount.Set(float64(count)) + s.regionScheduler.UpdateMetrics() + s.spanRegistry.UpdateMetrics() } } } // Subscribe the given table span. // NOTE: `span.TableID` must be set correctly. -// It new a subscribedSpan and store it in `s.totalSpans`, +// It new a subscribedSpan and store it in spanRegistry, // and send a rangeTask to `s.rangeTaskCh`. // The rangeTask will be handled in `handleRangeTasks` goroutine. func (s *subscriptionClient) Subscribe( @@ -362,13 +242,21 @@ func (s *subscriptionClient) Subscribe( return } - rt := s.newSubscribedSpan(subID, span, startTs, consumeKVEvents, advanceResolvedTs, advanceInterval, bdrMode) - s.totalSpans.Lock() - s.totalSpans.spanMap[subID] = rt - s.totalSpans.Unlock() + rt := newSubscribedSpan( + s.ctx, + s.resolveLockRateLimiter, + s.resolveLockTaskCh, + subID, + span, + startTs, + consumeKVEvents, + advanceResolvedTs, + advanceInterval, + bdrMode, + ) + s.spanRegistry.Add(rt) - areaSetting := dynstream.NewAreaSettingsWithMaxPendingSize(1*1024*1024*1024, dynstream.MemoryControlForPuller, "logPuller") // 1GB - s.ds.AddPath(rt.subID, rt, areaSetting) + s.eventSink.AddPath(rt) select { case <-s.ctx.Done(): @@ -383,10 +271,8 @@ func (s *subscriptionClient) Subscribe( // Unsubscribe the given table span. All covered regions will be deregistered asynchronously. // NOTE: `span.TableID` must be set correctly. func (s *subscriptionClient) Unsubscribe(subID SubscriptionID) { - // NOTE: `subID` is cleared from `s.totalSpans` in `onTableDrained`. - s.totalSpans.Lock() - rt := s.totalSpans.spanMap[subID] - s.totalSpans.Unlock() + // NOTE: `subID` is cleared from `spanRegistry` in `onTableDrained`. + rt := s.spanRegistry.Get(subID) if rt == nil { log.Warn("unknown subscription", zap.Uint64("subscriptionID", uint64(subID))) return @@ -398,75 +284,17 @@ func (s *subscriptionClient) Unsubscribe(subID SubscriptionID) { zap.Bool("exists", rt != nil)) } -func (s *subscriptionClient) wakeSubscription(subID SubscriptionID) { - s.ds.Wake(subID) -} - -func (s *subscriptionClient) pushRegionEventToDS(subID SubscriptionID, event regionEvent) { - // fast path - if !s.paused.Load() { - s.ds.Push(subID, event) - return - } - // slow path: wait until paused is false - s.mu.Lock() - for s.paused.Load() { - select { - case <-s.ctx.Done(): - s.mu.Unlock() - return - default: - s.cond.Wait() - } - } - s.mu.Unlock() - s.ds.Push(subID, event) -} - -func (s *subscriptionClient) handleDSFeedBack(ctx context.Context) error { - for { - select { - case <-ctx.Done(): - return nil - case feedback := <-s.ds.Feedback(): - switch feedback.FeedbackType { - case dynstream.PauseArea: - s.mu.Lock() - s.paused.Store(true) - s.mu.Unlock() - log.Info("subscription client pause push region event") - case dynstream.ResumeArea: - s.mu.Lock() - s.paused.Store(false) - s.cond.Broadcast() - s.mu.Unlock() - log.Info("subscription client resume push region event") - case dynstream.ReleasePath, dynstream.ResumePath: - // Ignore it, because it is no need to pause and resume a path in puller. - } - } - } -} - func (s *subscriptionClient) Run(ctx context.Context) error { - // s.consume = consume - if s.pd == nil { - log.Warn("subscription client should be in test mode, skip run") - return nil - } - s.clusterID = s.pd.GetClusterID(ctx) + s.upstream.Initialize(ctx) g, ctx := errgroup.WithContext(ctx) - - g.Go(func() error { return s.updateMetrics(ctx) }) - g.Go(func() error { return s.handleDSFeedBack(ctx) }) + g.Go(func() error { return s.eventSink.Run(ctx) }) + g.Go(func() error { return s.failureHandler.Run(ctx) }) + g.Go(func() error { return s.regionScheduler.Run(ctx, g) }) g.Go(func() error { return s.handleRangeTasks(ctx) }) - g.Go(func() error { return s.handleRegions(ctx, g) }) - g.Go(func() error { return s.handleErrors(ctx) }) - g.Go(func() error { return s.runResolveLockChecker(ctx) }) g.Go(func() error { return s.handleResolveLockTasks(ctx) }) - g.Go(func() error { return s.logSlowRegions(ctx) }) - g.Go(func() error { return s.errCache.dispatch(ctx) }) + g.Go(func() error { return s.spanRegistry.Run(ctx) }) + g.Go(func() error { return s.runMetricsUpdater(ctx) }) log.Info("subscription client starts") defer log.Info("subscription client exits") @@ -476,12 +304,10 @@ func (s *subscriptionClient) Run(ctx context.Context) error { // Close closes the client. Must be called after `Run` returns. func (s *subscriptionClient) Close(ctx context.Context) error { s.cancel() - s.mu.Lock() - s.paused.Store(false) - s.cond.Broadcast() - s.mu.Unlock() - s.ds.Close() - s.regionTaskQueue.Close() + s.eventSink.Close() + if s.regionScheduler != nil { + s.regionScheduler.Close() + } return nil } @@ -490,10 +316,9 @@ func (s *subscriptionClient) setTableStopped(rt *subscribedSpan) { zap.Uint64("subscriptionID", uint64(rt.subID))) // Set stopped to true so we can stop handling region events from the table. - // Then send a special singleRegionInfo to regionRouter to deregister the table - // from all TiKV instances. + // Then broadcast deregister requests to all region request workers. if rt.stopped.CompareAndSwap(false, true) { - s.regionTaskQueue.Push(NewRegionPriorityTask(TaskHighPrior, regionInfo{subscribedSpan: rt, filterLoop: rt.filterLoop}, s.pdClock.CurrentTS())) + s.regionScheduler.BroadcastDeregister(rt.subID, rt.filterLoop) if rt.rangeLock.Stop() { s.onTableDrained(rt) } @@ -504,198 +329,13 @@ func (s *subscriptionClient) onTableDrained(rt *subscribedSpan) { log.Info("subscription client stop span is finished", zap.Uint64("subscriptionID", uint64(rt.subID))) - err := s.ds.RemovePath(rt.subID) + err := s.eventSink.RemovePath(rt.subID) if err != nil { log.Warn("subscription client remove path failed", zap.Uint64("subscriptionID", uint64(rt.subID)), zap.Error(err)) } - s.totalSpans.Lock() - defer s.totalSpans.Unlock() - delete(s.totalSpans.spanMap, rt.subID) -} - -// Note: don't block the caller, otherwise there may be deadlock -func (s *subscriptionClient) onRegionFail(errInfo regionErrorInfo) { - // unlock the range early to prevent blocking the range. - if errInfo.subscribedSpan.rangeLock.UnlockRange( - errInfo.span.StartKey, errInfo.span.EndKey, - errInfo.verID.GetID(), errInfo.verID.GetVer(), errInfo.resolvedTs()) { - s.onTableDrained(errInfo.subscribedSpan) - return - } - s.errCache.add(errInfo) -} - -// requestedStore represents a store that has been connected. -type requestedStore struct { - storeAddr string - // Use to select a worker to send request. - nextWorker atomic.Uint32 - - requestWorkers struct { - sync.RWMutex - s []*regionRequestWorker - } -} - -func (rs *requestedStore) getRequestWorker() *regionRequestWorker { - rs.requestWorkers.RLock() - defer rs.requestWorkers.RUnlock() - - index := rs.nextWorker.Add(1) % uint32(len(rs.requestWorkers.s)) - return rs.requestWorkers.s[index] -} - -// handleRegions receives regionInfo from regionTaskQueue and attach rpcCtx to them, -// then send them to corresponding requestedStore. -func (s *subscriptionClient) handleRegions(ctx context.Context, eg *errgroup.Group) error { - cfg := config.GetGlobalServerConfig() - pendingRegionRequestQueueSize := cfg.Debug.Puller.PendingRegionRequestQueueSize - getStore := func(storeAddr string) *requestedStore { - var rs *requestedStore - if v, ok := s.stores.Load(storeAddr); ok { - rs = v.(*requestedStore) - return rs - } - - rs = &requestedStore{storeAddr: storeAddr} - rs.requestWorkers.s = make([]*regionRequestWorker, 0, s.config.RegionRequestWorkerPerStore) - s.stores.Store(storeAddr, rs) - - perWorkerQueueSize := pendingRegionRequestQueueSize / int(s.config.RegionRequestWorkerPerStore) - if perWorkerQueueSize <= 0 { - log.Warn("pending region request queue size is smaller than the number of workers, adjust per worker queue size to 1", - zap.Int("pendingRegionRequestQueueSize", pendingRegionRequestQueueSize), - zap.Uint("regionRequestWorkerPerStore", s.config.RegionRequestWorkerPerStore)) - perWorkerQueueSize = 1 - } - - rs.requestWorkers.Lock() - for i := uint(0); i < s.config.RegionRequestWorkerPerStore; i++ { - requestWorker := newRegionRequestWorker(ctx, s, s.credential, eg, rs, perWorkerQueueSize) - rs.requestWorkers.s = append(rs.requestWorkers.s, requestWorker) - } - rs.requestWorkers.Unlock() - return rs - } - - defer func() { - s.stores.Range(func(_, value any) bool { - rs := value.(*requestedStore) - - rs.requestWorkers.RLock() - for _, w := range rs.requestWorkers.s { - w.requestCache.clear() - } - rs.requestWorkers.RUnlock() - - return true - }) - }() - - for { - select { - case <-ctx.Done(): - return ctx.Err() - default: - } - // Use blocking Pop to wait for tasks - regionTask, err := s.regionTaskQueue.Pop(ctx) - if err != nil { - if errors.Is(err, priorityqueue.ErrClosed) { - return nil - } - return err - } - - region := regionTask.GetRegionInfo() - if region.isStopped() { - enqueued, err := s.enqueueRegionToAllStores(ctx, region) - if err != nil { - return err - } - if !enqueued { - log.Debug("enqueue stop request failed, retry later", - zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID))) - s.regionTaskQueue.Push(regionTask) - } - continue - } - - region, ok := s.attachRPCContextForRegion(ctx, region) - // If attachRPCContextForRegion fails, the region will be re-scheduled. - if !ok { - continue - } - - store := getStore(region.rpcCtx.Addr) - worker := store.getRequestWorker() - force := regionTask.Priority() <= forcedPriorityBase - - ok, err = worker.add(ctx, region, force) - if err != nil { - log.Warn("subscription client add region request failed", - zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID)), - zap.Uint64("regionID", region.verID.GetID()), - zap.Error(err)) - return err - } - - if !ok { - s.regionTaskQueue.Push(regionTask) - continue - } - - log.Debug("subscription client will request a region", - zap.Uint64("workID", worker.workerID), - zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID)), - zap.Uint64("regionID", region.verID.GetID()), - zap.String("addr", store.storeAddr)) - } -} - -func (s *subscriptionClient) enqueueRegionToAllStores(ctx context.Context, region regionInfo) (bool, error) { - enqueued := true - var firstErr error - s.stores.Range(func(_ any, value any) bool { - rs := value.(*requestedStore) - rs.requestWorkers.RLock() - workers := rs.requestWorkers.s - rs.requestWorkers.RUnlock() - for _, worker := range workers { - ok, err := worker.add(ctx, region, true) - if err != nil { - firstErr = err - enqueued = false - return false - } - if !ok { - enqueued = false - // It is likely the store is busy, no need to try other workers in this store now. - break - } - } - return true - }) - return enqueued, firstErr -} - -func (s *subscriptionClient) attachRPCContextForRegion(ctx context.Context, region regionInfo) (regionInfo, bool) { - bo := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) - rpcCtx, err := s.regionCache.GetTiKVRPCContext(bo, region.verID, kvclientv2.ReplicaReadLeader, 0) - if rpcCtx != nil { - region.rpcCtx = rpcCtx - return region, true - } - if err != nil { - log.Debug("subscription client get rpc context fail", - zap.Uint64("subscriptionID", uint64(region.subscribedSpan.subID)), - zap.Uint64("regionID", region.verID.GetID()), - zap.Error(err)) - } - s.onRegionFail(newRegionErrorInfo(region, &rpcCtxUnavailableErr{verID: region.verID})) - return region, false + s.spanRegistry.Remove(rt.subID) } func (s *subscriptionClient) handleRangeTasks(ctx context.Context) error { @@ -742,7 +382,7 @@ func (s *subscriptionClient) divideSpanAndScheduleRegionRequests( zap.Any("span", common.FormatTableSpan(&nextSpan))) backoff := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) - regions, err := s.regionCache.BatchLoadRegionsWithKeyRange(backoff, nextSpan.StartKey, nextSpan.EndKey, limit) + regions, err := s.upstream.regionCache.BatchLoadRegionsWithKeyRange(backoff, nextSpan.StartKey, nextSpan.EndKey, limit) if err != nil { log.Warn("subscription client load regions failed", zap.Uint64("subscriptionID", uint64(subscribedSpan.subID)), @@ -800,8 +440,8 @@ func (s *subscriptionClient) divideSpanAndScheduleRegionRequests( } } -// scheduleRegionRequest locks the region's range and send the region to regionTaskQueue, -// which will be handled by handleRegions. +// scheduleRegionRequest locks the region's range and submits it to the region +// request scheduler. func (s *subscriptionClient) scheduleRegionRequest(ctx context.Context, region regionInfo, priority TaskType) { lockRangeResult := region.subscribedSpan.rangeLock.LockRange( ctx, region.span.StartKey, region.span.EndKey, region.verID.GetID(), region.verID.GetVer()) @@ -813,7 +453,7 @@ func (s *subscriptionClient) scheduleRegionRequest(ctx context.Context, region r switch lockRangeResult.Status { case regionlock.LockRangeStatusSuccess: region.lockedRangeState = lockRangeResult.LockedRangeState - s.regionTaskQueue.Push(NewRegionPriorityTask(priority, region, s.pdClock.CurrentTS())) + s.regionScheduler.Submit(priority, region) case regionlock.LockRangeStatusStale: for _, r := range lockRangeResult.RetryRanges { s.scheduleRangeRequest(ctx, r, region.subscribedSpan, region.filterLoop, priority) @@ -835,167 +475,6 @@ func (s *subscriptionClient) scheduleRangeRequest( } } -func (s *subscriptionClient) handleErrors(ctx context.Context) error { - for { - select { - case <-ctx.Done(): - log.Info("subscription client handle errors and exit") - return ctx.Err() - case errInfo := <-s.errCache.errCh: - if err := s.doHandleError(ctx, errInfo); err != nil { - return err - } - } - } -} - -func (s *subscriptionClient) doHandleError(ctx context.Context, errInfo regionErrorInfo) error { - err := errors.Cause(errInfo.err) - if _, requestCancelled := err.(*requestCancelledErr); !requestCancelled { - log.Debug("cdc region error", - zap.Uint64("subscriptionID", uint64(errInfo.subscribedSpan.subID)), - zap.Uint64("regionID", errInfo.verID.GetID()), - zap.Error(err)) - } - - //nolint:errorlint // converting large type switch to errors.As is a significant refactor - switch eerr := err.(type) { - case *eventError: - innerErr := eerr.err - if notLeader := innerErr.GetNotLeader(); notLeader != nil { - metricFeedNotLeaderCounter.Inc() - s.regionCache.UpdateLeader(errInfo.verID, notLeader.GetLeader(), errInfo.rpcCtx.AccessIdx) - s.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) - return nil - } - if innerErr.GetEpochNotMatch() != nil { - metricFeedEpochNotMatchCounter.Inc() - s.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) - return nil - } - if innerErr.GetRegionNotFound() != nil { - metricFeedRegionNotFoundCounter.Inc() - s.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) - return nil - } - if innerErr.GetCongested() != nil { - metricKvCongestedCounter.Inc() - s.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskLowPrior) - return nil - } - if innerErr.GetServerIsBusy() != nil { - metricKvIsBusyCounter.Inc() - s.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskLowPrior) - return nil - } - if duplicated := innerErr.GetDuplicateRequest(); duplicated != nil { - // TODO(qupeng): It's better to add a new machanism to deregister one region. - metricFeedDuplicateRequestCounter.Inc() - return errors.New("duplicate request") - } - if compatibility := innerErr.GetCompatibility(); compatibility != nil { - return errors.ErrVersionIncompatible.GenWithStackByArgs(compatibility) - } - if mismatch := innerErr.GetClusterIdMismatch(); mismatch != nil { - return errors.ErrClusterIDMismatch.GenWithStackByArgs(mismatch.Current, mismatch.Request) - } - - log.Warn("empty or unknown cdc error", - zap.Uint64("subscriptionID", uint64(errInfo.subscribedSpan.subID)), - zap.Stringer("error", innerErr)) - metricFeedUnknownErrorCounter.Inc() - s.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) - return nil - case *rpcCtxUnavailableErr: - metricFeedRPCCtxUnavailable.Inc() - s.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) - return nil - case *getStoreErr: - metricGetStoreErr.Inc() - bo := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) - // cannot get the store the region belongs to, so we need to reload the region. - s.regionCache.OnSendFail(bo, errInfo.rpcCtx, true, err) - s.scheduleRangeRequest(ctx, errInfo.span, errInfo.subscribedSpan, errInfo.filterLoop, TaskHighPrior) - return nil - case *storeStreamErr: - metricStoreSendRequestErr.Inc() - bo := tikv.NewBackoffer(ctx, tikvRequestMaxBackoff) - s.regionCache.OnSendFail(bo, errInfo.rpcCtx, regionScheduleReload, err) - s.scheduleRegionRequest(ctx, errInfo.regionInfo, TaskHighPrior) - return nil - case *requestCancelledErr: - // the corresponding subscription has been unsubscribed, just ignore. - return nil - default: - // TODO(qupeng): for some errors it's better to just deregister the region from TiKVs. - log.Warn("subscription client meets an internal error, fail the changefeed", - zap.Uint64("subscriptionID", uint64(errInfo.subscribedSpan.subID)), - zap.Error(err)) - return err - } -} - -type subscriptionAndTargetTs struct { - subSpan *subscribedSpan - targetTs uint64 -} - -func (s *subscriptionClient) runResolveLockChecker(ctx context.Context) error { - resolveLockTicker := time.NewTicker(resolveLockTickInterval) - defer resolveLockTicker.Stop() - maxCacheSize := 1024 - subSpanAndTsCache := make([]subscriptionAndTargetTs, 0, maxCacheSize) - // getResolvedTargetTs returns the targetTs to resolve stale locks. 0 means no need to resolve. - getResolvedTargetTs := func(subSpan *subscribedSpan, currentTime time.Time, currentTs uint64) uint64 { - resolvedTsUpdated := time.Unix(subSpan.resolvedTsUpdated.Load(), 0) - if !subSpan.initialized.Load() || time.Since(resolvedTsUpdated) < resolveLockFence { - return 0 - } - resolvedTs := subSpan.resolvedTs.Load() - resolvedTime := oracle.GetTimeFromTS(resolvedTs) - if currentTime.Sub(resolvedTime) < resolveLockFence { - return 0 - } - return min(currentTs, oracle.GoTimeToTS(resolvedTime.Add(resolveLockFence))) - } - - for { - select { - case <-ctx.Done(): - return ctx.Err() - case <-resolveLockTicker.C: - } - - physical, logic, err := s.pd.GetTS(ctx) - if err != nil { - log.Warn("get ts from pd failed", zap.Error(err)) - continue - } - currentTs := oracle.ComposeTS(physical, logic) - currentTime := s.pdClock.CurrentTime() - s.totalSpans.Lock() - for _, subSpan := range s.totalSpans.spanMap { - if subSpan != nil { - targetTs := getResolvedTargetTs(subSpan, currentTime, currentTs) - if targetTs > 0 { - subSpanAndTsCache = append(subSpanAndTsCache, subscriptionAndTargetTs{ - subSpan: subSpan, - targetTs: targetTs, - }) - } - } - } - s.totalSpans.Unlock() - for _, subSpanAndTs := range subSpanAndTsCache { - subSpanAndTs.subSpan.resolveStaleLocks(subSpanAndTs.targetTs) - } - subSpanAndTsCache = subSpanAndTsCache[:0] - if cap(subSpanAndTsCache) > maxCacheSize { - subSpanAndTsCache = make([]subscriptionAndTargetTs, 0, maxCacheSize) - } - } -} - func (s *subscriptionClient) handleResolveLockTasks(ctx context.Context) error { doResolve := func(task resolveLockTask) { keyspaceID := task.keyspaceID @@ -1033,215 +512,3 @@ func (s *subscriptionClient) handleResolveLockTasks(ctx context.Context) error { } } } - -func (s *subscriptionClient) logSlowRegions(ctx context.Context) error { - ticker := time.NewTicker(30 * time.Second) - defer ticker.Stop() - for { - select { - case <-ctx.Done(): - return ctx.Err() - case <-ticker.C: - } - - currTime := s.pdClock.CurrentTime() - s.totalSpans.RLock() - slowInitializeRegion := 0 - for subscriptionID, rt := range s.totalSpans.spanMap { - attr := rt.rangeLock.IterAll(nil) - ckptTime := oracle.GetTimeFromTS(attr.SlowestRegion.ResolvedTs) - if attr.SlowestRegion.Initialized { - if currTime.Sub(ckptTime) > 6*resolveLockMinInterval { - log.Info("subscription client finds a initialized slow region", - zap.Uint64("subscriptionID", uint64(subscriptionID)), - zap.Any("slowRegion", attr.SlowestRegion)) - } - } else if currTime.Sub(attr.SlowestRegion.Created) > 10*time.Minute { - slowInitializeRegion++ - log.Info("subscription client initializes a region too slow", - zap.Uint64("subscriptionID", uint64(subscriptionID)), - zap.Any("slowRegion", attr.SlowestRegion)) - } else if currTime.Sub(ckptTime) > 10*time.Minute { - log.Info("subscription client finds a uninitialized slow region", - zap.Uint64("subscriptionID", uint64(subscriptionID)), - zap.Any("slowRegion", attr.SlowestRegion)) - } - if len(attr.UnLockedRanges) > 0 { - log.Info("subscription client holes exist", - zap.Uint64("subscriptionID", uint64(subscriptionID)), - zap.Any("holes", attr.UnLockedRanges)) - } - } - s.totalSpans.RUnlock() - } -} - -func (s *subscriptionClient) newSubscribedSpan( - subID SubscriptionID, - span heartbeatpb.TableSpan, - startTs uint64, - consumeKVEvents func(raw []common.RawKVEntry, wakeCallback func()) bool, - advanceResolvedTs func(ts uint64), - advanceInterval int64, - filterLoop bool, -) *subscribedSpan { - rangeLock := regionlock.NewRangeLock(uint64(subID), span.StartKey, span.EndKey, startTs) - - rt := &subscribedSpan{ - subID: subID, - span: span, - startTs: startTs, - filterLoop: filterLoop, - rangeLock: rangeLock, - - consumeKVEvents: consumeKVEvents, - advanceResolvedTs: advanceResolvedTs, - advanceInterval: advanceInterval, - } - rt.initialized.Store(false) - rt.resolvedTsUpdated.Store(time.Now().Unix()) - rt.resolvedTs.Store(startTs) - - rt.tryResolveLock = func(regionID uint64, state *regionlock.LockedRangeState) { - targetTs := rt.staleLocksTargetTs.Load() - if !state.Initialized.Load() || state.ResolvedTs.Load() >= targetTs { - return - } - key := resolveLockKey{keyspaceID: span.KeyspaceID, regionID: regionID} - if !s.resolveLockRateLimiter.trySchedule(key, time.Now()) { - return - } - select { - case <-s.ctx.Done(): - s.resolveLockRateLimiter.cancel(key) - case s.resolveLockTaskCh <- resolveLockTask{ - keyspaceID: span.KeyspaceID, - regionID: regionID, - targetTs: targetTs, - state: state, - }: - // it is ok to ignore resolve lock task when the channel is full - default: - s.resolveLockRateLimiter.cancel(key) - metrics.SubscriptionClientResolveLockTaskDropCounter.Inc() - } - } - return rt -} - -func (s *subscriptionClient) GetResolvedTsLag() float64 { - pullerMinResolvedTs := uint64(0) - s.totalSpans.RLock() - for _, rt := range s.totalSpans.spanMap { - resolvedTs := rt.resolvedTs.Load() - if pullerMinResolvedTs == 0 || resolvedTs < pullerMinResolvedTs { - pullerMinResolvedTs = resolvedTs - } - } - s.totalSpans.RUnlock() - if pullerMinResolvedTs == 0 { - return 0 - } - pdTime := s.pdClock.CurrentTime() - phyResolvedTs := oracle.ExtractPhysical(pullerMinResolvedTs) - lag := float64(oracle.GetPhysical(pdTime)-phyResolvedTs) / 1e3 - return lag -} - -func (r *subscribedSpan) resolveStaleLocks(targetTs uint64) { - util.MustCompareAndMonotonicIncrease(&r.staleLocksTargetTs, targetTs) - res := r.rangeLock.IterAll(r.tryResolveLock) - log.Debug("subscription client finds slow locked ranges", - zap.Uint64("subscriptionID", uint64(r.subID)), - zap.Any("ranges", res)) -} - -type errCache struct { - sync.Mutex - cache []regionErrorInfo - errCh chan regionErrorInfo - notify chan struct{} -} - -const errCacheDispatchBatchSize = 1024 - -func newErrCache() *errCache { - return &errCache{ - cache: make([]regionErrorInfo, 0, 1024), - errCh: make(chan regionErrorInfo, 4096), - notify: make(chan struct{}, 1024), - } -} - -func (e *errCache) add(errInfo regionErrorInfo) { - e.Lock() - defer e.Unlock() - e.cache = append(e.cache, errInfo) - select { - case e.notify <- struct{}{}: - default: - } -} - -func (e *errCache) popBatch(limit int) []regionErrorInfo { - e.Lock() - defer e.Unlock() - if len(e.cache) == 0 { - return nil - } - if limit <= 0 || limit > len(e.cache) { - limit = len(e.cache) - } - batch := make([]regionErrorInfo, limit) - copy(batch, e.cache[:limit]) - clear(e.cache[:limit]) - if limit == len(e.cache) { - e.cache = e.cache[:0] - } else { - e.cache = e.cache[limit:] - } - return batch -} - -func (e *errCache) dispatchBatch(ctx context.Context, limit int) (int, error) { - batch := e.popBatch(limit) - for _, errInfo := range batch { - select { - case <-ctx.Done(): - log.Info("subscription client dispatch err cache done") - return 0, ctx.Err() - case e.errCh <- errInfo: - } - } - return len(batch), nil -} - -func (e *errCache) dispatch(ctx context.Context) error { - ticker := time.NewTicker(10 * time.Millisecond) - defer ticker.Stop() - sendToErrCh := func() error { - for { - n, err := e.dispatchBatch(ctx, errCacheDispatchBatchSize) - if err != nil { - return err - } - if n < errCacheDispatchBatchSize { - return nil - } - } - } - for { - select { - case <-ctx.Done(): - return ctx.Err() - case <-ticker.C: - if err := sendToErrCh(); err != nil { - return err - } - case <-e.notify: - if err := sendToErrCh(); err != nil { - return err - } - } - } -} diff --git a/logservice/logpuller/subscription_client_test.go b/logservice/logpuller/subscription_client_test.go index b502c4d7d1..34dc76170b 100644 --- a/logservice/logpuller/subscription_client_test.go +++ b/logservice/logpuller/subscription_client_test.go @@ -29,6 +29,7 @@ import ( "github.com/pingcap/ticdc/pkg/metrics" "github.com/pingcap/ticdc/pkg/pdutil" "github.com/pingcap/ticdc/pkg/security" + "github.com/pingcap/ticdc/utils/chann" "github.com/pingcap/ticdc/utils/dynstream" "github.com/pingcap/ticdc/utils/priorityqueue" "github.com/pingcap/tidb/pkg/store/mockstore/mockcopr" @@ -57,8 +58,10 @@ func TestGenerateResolveLockTask(t *testing.T) { client := &subscriptionClient{ resolveLockTaskCh: make(chan resolveLockTask, 10), resolveLockRateLimiter: newResolveLockRateLimiter(), + upstream: &upstreamHandle{pdClock: pdutil.NewClock4Test()}, } client.ctx, client.cancel = context.WithCancel(context.Background()) + client.spanRegistry = newSpanRegistry(client.upstream) rawSpan := heartbeatpb.TableSpan{ TableID: 1, StartKey: []byte{'a'}, @@ -66,10 +69,19 @@ func TestGenerateResolveLockTask(t *testing.T) { } consumeKVEvents := func(_ []common.RawKVEntry, _ func()) bool { return false } advanceResolvedTs := func(ts uint64) {} - span := client.newSubscribedSpan(SubscriptionID(1), rawSpan, 100, consumeKVEvents, advanceResolvedTs, 0, false) - client.totalSpans.spanMap = make(map[SubscriptionID]*subscribedSpan) - client.totalSpans.spanMap[SubscriptionID(1)] = span - client.pdClock = pdutil.NewClock4Test() + span := newSubscribedSpan( + client.ctx, + client.resolveLockRateLimiter, + client.resolveLockTaskCh, + SubscriptionID(1), + rawSpan, + 100, + consumeKVEvents, + advanceResolvedTs, + 0, + false, + ) + client.spanRegistry.Add(span) // Lock a range, and then ResolveLock will trigger a task for it. res := span.rangeLock.LockRange(context.Background(), []byte{'b'}, []byte{'c'}, 1, 100) @@ -94,11 +106,12 @@ func TestGenerateResolveLockTask(t *testing.T) { worker := ®ionRequestWorker{ requestCache: &requestCache{}, + tracker: newRegionTracker(0), } // Lock another range, no task will be triggered before initialized. res = span.rangeLock.LockRange(context.Background(), []byte{'c'}, []byte{'d'}, 2, 100) require.Equal(t, regionlock.LockRangeStatusSuccess, res.Status) - state := newRegionFeedState(regionInfo{lockedRangeState: res.LockedRangeState, subscribedSpan: span}, 1, worker) + state := newRegionFeedState(regionInfo{lockedRangeState: res.LockedRangeState, subscribedSpan: span}, 1, worker, nil) span.resolveStaleLocks(200) select { case <-client.resolveLockTaskCh: @@ -136,12 +149,12 @@ func TestResolveLockTaskDeduplicatedAcrossSubscribedSpans(t *testing.T) { consumeKVEvents := func(_ []common.RawKVEntry, _ func()) bool { return false } advanceResolvedTs := func(ts uint64) {} - span1 := client.newSubscribedSpan(SubscriptionID(1), heartbeatpb.TableSpan{ + span1 := newSubscribedSpan(client.ctx, client.resolveLockRateLimiter, client.resolveLockTaskCh, SubscriptionID(1), heartbeatpb.TableSpan{ TableID: 1, StartKey: []byte{'a'}, EndKey: []byte{'z'}, }, 100, consumeKVEvents, advanceResolvedTs, 0, false) - span2 := client.newSubscribedSpan(SubscriptionID(2), heartbeatpb.TableSpan{ + span2 := newSubscribedSpan(client.ctx, client.resolveLockRateLimiter, client.resolveLockTaskCh, SubscriptionID(2), heartbeatpb.TableSpan{ TableID: 2, StartKey: []byte{'a'}, EndKey: []byte{'z'}, @@ -244,7 +257,18 @@ func TestResolveLockTaskDroppedWhenChannelFull(t *testing.T) { } consumeKVEvents := func(_ []common.RawKVEntry, _ func()) bool { return false } advanceResolvedTs := func(ts uint64) {} - span := client.newSubscribedSpan(SubscriptionID(1), rawSpan, 100, consumeKVEvents, advanceResolvedTs, 0, false) + span := newSubscribedSpan( + client.ctx, + client.resolveLockRateLimiter, + client.resolveLockTaskCh, + SubscriptionID(1), + rawSpan, + 100, + consumeKVEvents, + advanceResolvedTs, + 0, + false, + ) res := span.rangeLock.LockRange(context.Background(), []byte{'b'}, []byte{'c'}, 1, 100) require.Equal(t, regionlock.LockRangeStatusSuccess, res.Status) @@ -279,11 +303,12 @@ func TestResolveLockTaskDroppedWhenChannelFull(t *testing.T) { func TestStopTaskUsesSubscribedSpanFilterLoop(t *testing.T) { client := &subscriptionClient{ resolveLockTaskCh: make(chan resolveLockTask, 1), - regionTaskQueue: priorityqueue.New[PriorityTask](), + upstream: &upstreamHandle{pdClock: pdutil.NewClock4Test()}, + eventSink: ®ionEventSink{ds: &mockDynamicStream{}}, } client.ctx, client.cancel = context.WithCancel(context.Background()) defer client.cancel() - client.pdClock = pdutil.NewClock4Test() + client.regionScheduler = newRegionRequestScheduler(client) rawSpan := heartbeatpb.TableSpan{ TableID: 1, @@ -292,27 +317,41 @@ func TestStopTaskUsesSubscribedSpanFilterLoop(t *testing.T) { } consumeKVEvents := func(_ []common.RawKVEntry, _ func()) bool { return false } advanceResolvedTs := func(ts uint64) {} - span := client.newSubscribedSpan(SubscriptionID(1), rawSpan, 100, consumeKVEvents, advanceResolvedTs, 0, true) + span := newSubscribedSpan( + client.ctx, + client.resolveLockRateLimiter, + client.resolveLockTaskCh, + SubscriptionID(1), + rawSpan, + 100, + consumeKVEvents, + advanceResolvedTs, + 0, + true, + ) res := span.rangeLock.LockRange(context.Background(), rawSpan.StartKey, rawSpan.EndKey, 1, 1) require.Equal(t, regionlock.LockRangeStatusSuccess, res.Status) + worker := ®ionRequestWorker{controlQueue: newControlQueue()} + store := &requestedStore{scheduler: client.regionScheduler, storeAddr: "store-1"} + store.requestWorkers = []*regionRequestWorker{worker} + client.regionScheduler.stores.Store(store.storeAddr, store) + client.setTableStopped(span) - ctx, cancel := context.WithTimeout(context.Background(), time.Second) - defer cancel() - task, err := client.regionTaskQueue.Pop(ctx) - require.NoError(t, err) - region := task.GetRegionInfo() - require.True(t, region.isStopped()) - require.True(t, region.filterLoop) + req, ok := worker.controlQueue.tryPop() + require.True(t, ok) + require.Equal(t, SubscriptionID(1), req.subID) + require.True(t, req.filterLoop) } func TestOnRegionFailQueuesCanceledErrorCache(t *testing.T) { client := &subscriptionClient{ - errCache: newErrCache(), - ds: &mockDynamicStream{}, + eventSink: ®ionEventSink{ds: &mockDynamicStream{}}, } + client.spanRegistry = newSpanRegistry(&upstreamHandle{}) + client.failureHandler = newRegionFailureHandler(&upstreamHandle{}, client.onTableDrained, nil, nil) rawSpan := heartbeatpb.TableSpan{ TableID: 1, StartKey: []byte("a"), @@ -323,7 +362,7 @@ func TestOnRegionFailQueuesCanceledErrorCache(t *testing.T) { span: rawSpan, rangeLock: regionlock.NewRangeLock(1, rawSpan.StartKey, rawSpan.EndKey, 100), } - client.totalSpans.spanMap = map[SubscriptionID]*subscribedSpan{span.subID: span} + client.spanRegistry.Add(span) res1 := span.rangeLock.LockRange(context.Background(), []byte("a"), []byte("m"), 1, 1) require.Equal(t, regionlock.LockRangeStatusSuccess, res1.Status) @@ -331,25 +370,58 @@ func TestOnRegionFailQueuesCanceledErrorCache(t *testing.T) { require.Equal(t, regionlock.LockRangeStatusSuccess, res2.Status) require.False(t, span.rangeLock.Stop()) - client.onRegionFail(newRegionErrorInfo(regionInfo{ + client.failureHandler.Report(newRegionErrorInfo(regionInfo{ verID: tikv.NewRegionVerID(1, 1, 1), span: heartbeatpb.TableSpan{TableID: 1, StartKey: []byte("a"), EndKey: []byte("m")}, subscribedSpan: span, lockedRangeState: res1.LockedRangeState, }, &requestCancelledErr{})) - require.Len(t, client.errCache.cache, 1) + require.Len(t, client.failureHandler.cache.cache, 1) require.Len(t, span.rangeLock.IterAll(nil).UnLockedRanges, 1) - client.onRegionFail(newRegionErrorInfo(regionInfo{ + client.failureHandler.Report(newRegionErrorInfo(regionInfo{ verID: tikv.NewRegionVerID(2, 1, 1), span: heartbeatpb.TableSpan{TableID: 1, StartKey: []byte("m"), EndKey: []byte("z")}, subscribedSpan: span, lockedRangeState: res2.LockedRangeState, }, &requestCancelledErr{})) - require.Len(t, client.errCache.cache, 1) - require.NotContains(t, client.totalSpans.spanMap, span.subID) + require.Len(t, client.failureHandler.cache.cache, 1) + require.Nil(t, client.spanRegistry.Get(span.subID)) +} + +func TestRegionFailureHandlerReschedulesRegionWhenRPCCtxChanged(t *testing.T) { + var regionScheduleCount int + var rangeScheduleCount int + var scheduledPriority TaskType + handler := newRegionFailureHandler( + &upstreamHandle{}, + func(*subscribedSpan) {}, + func(_ context.Context, _ regionInfo, priority TaskType) { + regionScheduleCount++ + scheduledPriority = priority + }, + func(_ context.Context, _ heartbeatpb.TableSpan, _ *subscribedSpan, _ bool, _ TaskType) { + rangeScheduleCount++ + }, + ) + + span := &subscribedSpan{subID: SubscriptionID(1)} + region := regionInfo{ + verID: tikv.NewRegionVerID(1, 1, 1), + subscribedSpan: span, + } + err := handler.handleError(t.Context(), newRegionErrorInfo(region, &rpcCtxChangedError{ + verID: region.verID, + from: "store-1", + to: "store-2", + })) + + require.NoError(t, err) + require.Equal(t, 1, regionScheduleCount) + require.Equal(t, 0, rangeScheduleCount) + require.Equal(t, TaskHighPrior, scheduledPriority) } type mockDynamicStream struct{} @@ -383,18 +455,16 @@ func (s *mockDynamicStream) GetMetrics() dynstream.Metrics[int, SubscriptionID] } func TestPushRegionEventToDSUnblocksOnClose(t *testing.T) { - client := &subscriptionClient{ - ds: &mockDynamicStream{}, - regionTaskQueue: priorityqueue.New[PriorityTask](), - } - client.ctx, client.cancel = context.WithCancel(context.Background()) - client.cond = sync.NewCond(&client.mu) + ctx, cancel := context.WithCancel(context.Background()) + sink := ®ionEventSink{ctx: ctx, ds: &mockDynamicStream{}} + sink.cond = sync.NewCond(&sink.mu) + client := &subscriptionClient{cancel: cancel, eventSink: sink} - client.paused.Store(true) + sink.paused.Store(true) done := make(chan struct{}) go func() { - client.pushRegionEventToDS(SubscriptionID(1), regionEvent{}) + sink.Push(SubscriptionID(1), regionEvent{}) close(done) }() @@ -413,39 +483,91 @@ func TestPushRegionEventToDSUnblocksOnClose(t *testing.T) { } } -func TestEnqueueRegionToAllStoresRetryWhenCacheFull(t *testing.T) { +func TestEnqueueDeregisterToAllStoresUsesControlQueue(t *testing.T) { ctx := context.Background() - client := &subscriptionClient{} + client := &subscriptionClient{upstream: &upstreamHandle{}} + scheduler := newRegionRequestScheduler(client) worker := ®ionRequestWorker{ - requestCache: newRequestCache(1), + requestCache: newRequestCache(1, nil), + controlQueue: newControlQueue(), } - store := &requestedStore{storeAddr: "store-1"} - store.requestWorkers.s = []*regionRequestWorker{worker} - client.stores.Store(store.storeAddr, store) + store := &requestedStore{scheduler: scheduler, storeAddr: "store-1"} + store.requestWorkers = []*regionRequestWorker{worker} + scheduler.stores.Store(store.storeAddr, store) dummyRegion := regionInfo{ subscribedSpan: &subscribedSpan{subID: SubscriptionID(2)}, lockedRangeState: ®ionlock.LockedRangeState{}, } - ok, err := worker.add(ctx, dummyRegion, true) + ok, err := worker.requestCache.add(ctx, dummyRegion, true, testRegionRequestQuota()) require.NoError(t, err) require.True(t, ok) - stopRegion := regionInfo{ - subscribedSpan: &subscribedSpan{subID: SubscriptionID(1)}, + scheduler.BroadcastDeregister(SubscriptionID(1), true) + require.Equal(t, 1, worker.controlQueue.len()) + req, ok := worker.controlQueue.tryPop() + require.True(t, ok) + require.Equal(t, SubscriptionID(1), req.subID) + require.True(t, req.filterLoop) + require.Equal(t, 1, worker.requestCache.pendingCount()) +} + +func TestRequestedStoreDeferredTasksPriority(t *testing.T) { + store := &requestedStore{storeAddr: "store-1", pendingTasks: priorityqueue.New[*regionPriorityTask]()} + currentTs := oracle.GoTimeToTS(time.Now()) + span := &subscribedSpan{subID: SubscriptionID(1)} + span.resolvedTs.Store(currentTs) + region := regionInfo{subscribedSpan: span} + + lowTask := newRegionPriorityTask(TaskLowPrior, region, currentTs, 1) + highTask := newRegionPriorityTask(TaskHighPrior, region, currentTs, 2) + + store.pendingTasks.Push(lowTask) + store.pendingTasks.Push(highTask) + + task, ok := store.pendingTasks.TryPop() + require.True(t, ok) + require.Same(t, highTask, task) + task, ok = store.pendingTasks.TryPop() + require.True(t, ok) + require.Same(t, lowTask, task) + _, ok = store.pendingTasks.TryPop() + require.False(t, ok) +} + +func TestRequestedStoreQuotaReleaseNotifiesSchedulerOnce(t *testing.T) { + scheduler := ®ionRequestScheduler{ + schedulerNotify: make(chan struct{}, 1), + storeAvailable: chann.NewUnlimitedChannelDefault[*requestedStore](), } - enqueued, err := client.enqueueRegionToAllStores(ctx, stopRegion) - require.NoError(t, err) - require.False(t, enqueued) + store := &requestedStore{scheduler: scheduler, storeAddr: "store-1"} + store.quota = newStoreQuota(1, store.NotifyAvailable) - <-worker.requestCache.pendingQueue - worker.requestCache.markDone() + quota, ok := store.quota.TryAcquire() + require.True(t, ok) + _, ok = store.quota.TryAcquire() + require.False(t, ok) - enqueued, err = client.enqueueRegionToAllStores(ctx, stopRegion) + quota.Release() + quota.Release() + require.Equal(t, 1, scheduler.storeAvailable.Len()) + select { + case <-scheduler.schedulerNotify: + default: + require.Fail(t, "quota release should notify scheduler") + } + + readyStore, ok, err := scheduler.storeAvailable.GetWithContext(context.Background()) require.NoError(t, err) - require.True(t, enqueued) - require.Equal(t, 1, len(worker.requestCache.pendingQueue)) + require.True(t, ok) + require.Same(t, store, readyStore) + readyStore.MarkAvailableDequeued() + + quota, ok = store.quota.TryAcquire() + require.True(t, ok) + quota.Release() + require.Equal(t, 1, scheduler.storeAvailable.Len()) } func TestSubscriptionWithFailedTiKV(t *testing.T) { @@ -478,7 +600,8 @@ func TestSubscriptionWithFailedTiKV(t *testing.T) { cluster.Bootstrap(11, []uint64{1, 2, 3}, []uint64{4, 5, 6}, 6) clientConfig := &SubscriptionClientConfig{ - RegionRequestWorkerPerStore: 2, + RegionRequestWorkerPerStore: 2, + PendingRegionRequestQueueSize: 32, } client := NewSubscriptionClient( clientConfig, @@ -704,14 +827,14 @@ func TestGetResolvedTargetTs(t *testing.T) { consumeKVEvents := func(_ []common.RawKVEntry, _ func()) bool { return false } advanceResolvedTs := func(ts uint64) {} - span := client.newSubscribedSpan(SubscriptionID(1), heartbeatpb.TableSpan{ + span := newSubscribedSpan(client.ctx, client.resolveLockRateLimiter, client.resolveLockTaskCh, SubscriptionID(1), heartbeatpb.TableSpan{ TableID: 1, StartKey: []byte{'a'}, EndKey: []byte{'z'}, }, 100, consumeKVEvents, advanceResolvedTs, 0, false) span.initialized.Store(true) - // Replicate the getResolvedTargetTs closure from runResolveLockChecker + // Replicate the getResolvedTargetTs closure from spanRegistry.runResolveLockChecker. getResolvedTargetTs := func(subSpan *subscribedSpan, currentTime time.Time, currentTs uint64) uint64 { resolvedTsUpdated := time.Unix(subSpan.resolvedTsUpdated.Load(), 0) if !subSpan.initialized.Load() || time.Since(resolvedTsUpdated) < resolveLockFence { diff --git a/pkg/metrics/log_puller.go b/pkg/metrics/log_puller.go index e874aa4428..7b791249a7 100644 --- a/pkg/metrics/log_puller.go +++ b/pkg/metrics/log_puller.go @@ -80,6 +80,49 @@ var ( Name: "requested_region_count", Help: "The number of requested regions", }, []string{"state"}) + SubscriptionClientWorkerPendingRegionCount = prometheus.NewGaugeVec( + prometheus.GaugeOpts{ + Namespace: "ticdc", + Subsystem: "subscription_client", + Name: "worker_pending_region_count", + Help: "The number of pending region requests in each worker", + }, []string{"store", "worker"}) + SubscriptionClientStoreDeferredRegionCount = prometheus.NewGaugeVec( + prometheus.GaugeOpts{ + Namespace: "ticdc", + Subsystem: "subscription_client", + Name: "store_deferred_region_count", + Help: "The number of deferred region requests for each store", + }, []string{"store"}) + SubscriptionClientStoreQuotaGauge = prometheus.NewGaugeVec( + prometheus.GaugeOpts{ + Namespace: "ticdc", + Subsystem: "subscription_client", + Name: "store_region_request_quota", + Help: "The region request quota usage for each store", + }, []string{"store", "type"}) + SubscriptionClientRegionRequestSendCounter = prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: "ticdc", + Subsystem: "subscription_client", + Name: "region_request_send_count", + Help: "The number of region requests sent to TiKV", + }, []string{"store", "worker"}) + SubscriptionClientRegionRequestDeferCounter = prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: "ticdc", + Subsystem: "subscription_client", + Name: "region_request_defer_count", + Help: "The number of region requests deferred by the scheduler", + }, []string{"store", "reason"}) + SubscriptionClientRegionRequestAdmitDuration = prometheus.NewHistogram( + prometheus.HistogramOpts{ + Namespace: "ticdc", + Subsystem: "subscription_client", + Name: "region_request_admit_duration", + Help: "duration (s) from region request task creation to admission into a worker", + Buckets: prometheus.ExponentialBuckets(0.00004, 2.0, 28), // 40us to 1.5h + }) RegionRequestFinishScanDuration = prometheus.NewHistogram( prometheus.HistogramOpts{ Namespace: "ticdc", @@ -165,6 +208,12 @@ func initLogPullerMetrics(registry *prometheus.Registry) { registry.MustRegister(LogPullerMatcherCount) registry.MustRegister(LogPullerResolvedTsLag) registry.MustRegister(SubscriptionClientRequestedRegionCount) + registry.MustRegister(SubscriptionClientWorkerPendingRegionCount) + registry.MustRegister(SubscriptionClientStoreDeferredRegionCount) + registry.MustRegister(SubscriptionClientStoreQuotaGauge) + registry.MustRegister(SubscriptionClientRegionRequestSendCounter) + registry.MustRegister(SubscriptionClientRegionRequestDeferCounter) + registry.MustRegister(SubscriptionClientRegionRequestAdmitDuration) registry.MustRegister(SubscriptionClientAddRegionRequestDuration) registry.MustRegister(RegionRequestFinishScanDuration) registry.MustRegister(SubscriptionClientSubscribedRegionCount) diff --git a/server/server.go b/server/server.go index b9dc5edad8..2e83359930 100644 --- a/server/server.go +++ b/server/server.go @@ -199,7 +199,8 @@ func (c *server) initialize(ctx context.Context) error { schemaStore := schemastore.New(conf.DataDir, c.pdClient) subscriptionClient := logpuller.NewSubscriptionClient( &logpuller.SubscriptionClientConfig{ - RegionRequestWorkerPerStore: 8, + RegionRequestWorkerPerStore: 8, + PendingRegionRequestQueueSize: conf.Debug.Puller.PendingRegionRequestQueueSize, }, c.pdClient, txnutil.NewLockerResolver(), c.security, diff --git a/utils/notifyqueue/notify_queue.go b/utils/notifyqueue/notify_queue.go new file mode 100644 index 0000000000..331aaf4b02 --- /dev/null +++ b/utils/notifyqueue/notify_queue.go @@ -0,0 +1,77 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package notifyqueue provides a FIFO queue with a selectable ready signal. +package notifyqueue + +import "github.com/pingcap/ticdc/utils/deque" + +// Queue is a FIFO queue with a wake-up channel. +// +// Queue is not safe for concurrent use. Callers must serialize Push, TryPop, +// Drain, and Len by themselves. +// +// Ready returns a wake-up hint. Receiving from it does not guarantee TryPop +// will return an item, and callers must re-check the queue state after wake-up. +type Queue[T any] struct { + queue *deque.Deque[T] + ready chan struct{} +} + +// New creates an empty Queue. +func New[T any]() *Queue[T] { + return &Queue[T]{ + queue: deque.NewDequeDefault[T](), + ready: make(chan struct{}, 1), + } +} + +// Push appends an item and signals Ready. +func (q *Queue[T]) Push(item T) { + q.queue.PushBack(item) + q.signal() +} + +// TryPop pops one item from the front of the queue. +func (q *Queue[T]) TryPop() (T, bool) { + return q.queue.PopFront() +} + +// Drain removes and returns all queued items in FIFO order. +func (q *Queue[T]) Drain() []T { + items := make([]T, 0, q.queue.Length()) + for { + item, ok := q.queue.PopFront() + if !ok { + return items + } + items = append(items, item) + } +} + +// Len returns the number of queued items. +func (q *Queue[T]) Len() int { + return q.queue.Length() +} + +// Ready returns a wake-up channel for consumers. +func (q *Queue[T]) Ready() <-chan struct{} { + return q.ready +} + +func (q *Queue[T]) signal() { + select { + case q.ready <- struct{}{}: + default: + } +} diff --git a/utils/notifyqueue/notify_queue_test.go b/utils/notifyqueue/notify_queue_test.go new file mode 100644 index 0000000000..1532f23d3d --- /dev/null +++ b/utils/notifyqueue/notify_queue_test.go @@ -0,0 +1,83 @@ +// Copyright 2026 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package notifyqueue + +import ( + "testing" + + "github.com/stretchr/testify/require" +) + +func TestQueuePushPopAndReady(t *testing.T) { + q := New[int]() + + select { + case <-q.Ready(): + t.Fatal("empty queue should not be ready") + default: + } + + q.Push(1) + q.Push(2) + require.Equal(t, 2, q.Len()) + + select { + case <-q.Ready(): + default: + t.Fatal("push should signal ready") + } + + v, ok := q.TryPop() + require.True(t, ok) + require.Equal(t, 1, v) + v, ok = q.TryPop() + require.True(t, ok) + require.Equal(t, 2, v) + require.Equal(t, 0, q.Len()) + + _, ok = q.TryPop() + require.False(t, ok) +} + +func TestQueueReadyIsCoalesced(t *testing.T) { + q := New[int]() + + q.Push(1) + q.Push(2) + + select { + case <-q.Ready(): + default: + t.Fatal("push should signal ready") + } + + select { + case <-q.Ready(): + t.Fatal("ready signal should be coalesced") + default: + } +} + +func TestQueueDrain(t *testing.T) { + q := New[int]() + q.Push(1) + q.Push(2) + q.Push(3) + + require.Equal(t, []int{1, 2, 3}, q.Drain()) + require.Equal(t, 0, q.Len()) + + _, ok := q.TryPop() + require.False(t, ok) +}