kv: Fix a race in catchup scan completion that may send an error.

[miretskiy]

As noticed by @nvanbenschoten , it is possible that while the catchup scan running,
the buffer for raft events may get over full, and in that case, when catchup scan completes,
we may send an overfull error instead of checkpoint event. We should prioritize sending
checkpoint event.

CRDB-8666

Jira issue: CRDB-13720

[blathers-crl]

cc @cockroachdb/cdc

[nvanbenschoten]

We should prioritize sending checkpoint event.

Specifically, we should prioritize sending a checkpoint event that contains a non-zero timestamp after a catch-up scan completes and before the registration consults its overflowed flag. In doing so, we ensure progress¹ of the rangefeed across per-range retries due to REASON_SLOW_CONSUMER errors that are often tied to large catch-up scans. Without this, we have no guarantee that a large catch-up scan's progress will be locked in and that it won't retry indefinitely.

Ensuring this is going to be a little tricky, because a non-zero checkpoint timestamp depends on the completion of the initResolvedTSScan. Now that this scan only consults the separated lock table (as of #71295), it seems reasonable to make tailing the raft log wait on its completion. Further care will need to be taken with the resolvedTimestamp to avoid clobering the initial closed timestamp (as of the point of registration) so that the resolved timestamp after the catch-up scan is applicable to the current state of the registration and not too advanced.

Footnotes

1. "progress" meaning that on a reconnection, the per-range "cursor" timestamp is larger than before. The client-side interaction points between checkpoints and retry timestamps are here, here, and here. ↩

[nvanbenschoten]

Making guarantees here seems difficult due to the shared resolvedTimestamp tracking (and associated unresolvedTxnHeap), which lives above the level of individual registration buffers. This means that even when a single registration's buffer overflows, the shared resolvedTimestamp tracking continues to advance. As a result, once an individual registration's buffer overflows, it often hasn't and can't publish the incremental changes necessary to use the shared resolved timestamp.

An option that avoids this issue is to allow each individual registration to perform its own initResolvedTSScan at its original log index (i.e. with an iterator captured under the raftMu when it began tailing the raft log). The registration could combine this with the closed timestamp from the original log index to construct a checkpoint to publish before erroring out. To avoid this costing too much under steady-state operation, we could limit this extra scan to only registrations that hit REASON_SLOW_CONSUMER errors before they publish their first non-zero checkpoint.

[nvanbenschoten]

I think the original premise for this issue was moderately incorrect. We only return a REASON_SLOW_CONSUMER error when the registration's buffer hits a size limit after draining the buffer. So the initial empty checkpoint will be published in this case.

However, the later realization that an empty checkpoint is insufficient to ensure forward progress remains. There's no guarantee that any non-empty checkpoint will land in the buffer before it reaches capacity.

I have a prototype that implements the "allow each individual registration to perform its own initResolvedTSScan" approach, but it is moderately complex. I'd be interested in determining how frequently we hit this case of only publishing an empty checkpoint before returning a REASON_SLOW_CONSUMER error. @miretskiy do we have any tests that demonstrate this starvation behavior, combining large catch-up scans with heavy foreground traffic?

[miretskiy]

No, I don't think we have that. What we know is that the catchup scan was long time in the past, and that the data included large JSONb blobs, so that the consumer was not too fast to consume.

[nvanbenschoten]

#77724 prototypes a fix for this issue.

As I mentioned in the PR, I don't think we should try to merge it right away. Instead, I think we should add instrumentation (logging or a metric) to help us determine whether this is a real problem in these cases. There is a race here, but it is less severe than previously believed, so it's not clear whether this is actually leading to starvation or not.

[miretskiy]

Customer enabled vlogging in distsender, and we appear to be hitting slow consumers errors very frequently.
I think ability to make forward progress upon catchup completion is very important.

[miretskiy]

@nvanbenschoten just want to make sure you saw the comment above -- do you think we should
resurrect your PR?

[nvanbenschoten]

@miretskiy thanks for letting me know. If we are seeing the theorized starvation in practice then I do think it's worthwhile to resurrect the PR. In the logs, did we repeatedly see the REASON_SLOW_CONSUMER error before a non-empty checkpoint?

I can take this as an action item for v23.1. Do we need it sooner?

do we have any tests that demonstrate this starvation behavior, combining large catch-up scans with heavy foreground traffic?

I think this kind of test would be worthwhile to demonstrate this behavior. It would also force us to express the relationship between catch-up scan throughput per range, new write throughput per range, and rangefeed-level buffering per-range. It would be nice to be able to say that a rangefeed (with retry loop) will always be able to eventually catch-up and establish a stable connection if catch_up_rate > new_write_rate, regardless of buffer size.