kv: closed timestamp can starve read-write txns that take longer than 600ms

[nvanbenschoten]

Now that we've dropped kv.closed_timestamp.target_duration down to 3s, we've seen an increase in read-write mutations that get starved by the closed timestamp. The earlier understanding was that these transactions would only be bumped by the closed timestamp if they took over 3s to commit, and would then be given 3s to refresh and complete their final batch if not. This first part is true, but the second part was a misunderstanding.

If a transaction takes more than 3s it will be bumped up to the current closed timestamp's value. It will then hit a retry error on its EndTxn batch. It will refresh at the old closed timestamp value and then try to commit again. If this commit is again bumped by the closed timestamp, we can enter a refresh loop that will terminate after 5 attempts and then be kicked back to the client. Since we're only ever refreshing up to the current closed timestamp, the transaction actually only has kv.closed_timestamp.target_duration * kv.closed_timestamp.close_fraction = 600ms to refresh and commit.

The easiest way to reproduce this is to perform a large DELETE statement in an implicit txn. If the DELETE takes long enough, it can get stuck in a starvation loop. This looks something like:

1. read all rows: Batch{Scan, Scan, ...}
2. try to delete all rows and commit: Batch{Delete, Delete, ..., EndTxn}
3. first two steps take over 3s so batch is pushed to `now - 3s` and hits a retry error when evaluating its EndTxn
4. refresh @ now - 3s
5. retry Batch{Delete, Delete, ..., EndTxn}
6. steps 4 and 5 took over 600ms so batch is pushed to `now - 3s`
7. retry for 5 times until giving up and either returning error to client or retrying in conn_executor 

This starvation is clearly undesirable, but it doesn't seem fundamental. There seems to be a few different things we could do here to improve the situation:

1. if the closed timestamp bumped victims up to the present time instead of its current value, requests would be given more time to refresh and complete: 3s instead of 600ms. This would avoid a large class of these issues, in exchange for increasing the chance that refreshes fail under contention and increasing the contention footprint of transactions that get bumped by the closed timestamp.
2. we noticed in storage: adaptive closed timestamp target duration #36478 that we don't need to respect the closed timestamp when re-writing intents. This means that we could avoid getting bumped by the closed timestamp in step 5 when retrying the batch of DELETEs. OR, we could revive an optimization we had previously removed and avoid issuing that prefix of the batch entirely after the refresh since it had already succeeded. We probably don't want to do this second part because it gets confusing and may not be as useful in the context of parallel commits.
3. we also noticed in storage: adaptive closed timestamp target duration #36478 that EndTxn requests don't need to respect the closed timestamp. This means that we could ignore the closed timestamp entirely when issuing an EndTxn.

So in an optimal world, step 5 would be able to ignore the closed timestamp entirely as long as its intents were previously written in step 2.

[aayushshah15]

While stressing kvnemesis with merges enabled for #50265 (though I can reproduce this failure mode with and without that PR), I ran into timeouts that seem to be caused by roughly what this issue describes.

cockroach/pkg/kv/kvnemesis/kvnemesis_test.go

Lines 71 to 74 in 053ec8b

	// kvnemesis found a rare bug with closed timestamps when merges happen
	// on a multinode cluster. Disable the combo for now to keep the test
	// from flaking. See #44878.
	config.Ops.Merge = MergeConfig{}

I was using a relatively low closed timestamp duration (500ms) because that was more likely to lead to scenarios like the one that PR fixes. I noticed that txns that scanned a lot of keys and then wrote something would refresh/retry a lot (what this issue talks about). However, the logs also indicate that a ton of time was being spent pushing conflicting transactions.

and also that the sort of transactions that can end up in this endless retry loop seem to also have long queues of pusher txns waiting on them. I saw over 1000 pending txns in my logs waiting on one such endlessly-retrying txn (highest epoch I saw for it was ~50).

Maybe I’m missing something here, but I don’t see anything preventing this sort of transitive starvation (of the waiting pushers). The select case in MaybeWaitForPush queries for the pushee’s state every 5 seconds and just loops back if the pushee hasn’t been committed or aborted. It doesn’t care whether the pushee has already had its timestamp already bumped somehow.

When I don’t use a low closed timestamp, I can’t reproduce this failure mode.

Edit: Here is a log file from one such run in case someone is interested:
lot_of_pushers_in_wait_queue.zip
(apologies for the extremely verbose logs, the pushee that a ton of pushers were waiting on has txn id: c4a330aa)

[andreimatei]

Maybe I’m missing something here, but I don’t see anything preventing this sort of transitive starvation (of the waiting pushers). The select case in MaybeWaitForPush queries for the pushee’s state every 5 seconds and just loops back if the pushee hasn’t been committed or aborted. It doesn’t care whether the pushee has already had its timestamp already bumped somehow.

This is tangential to the issue, but I would have guessed that readers at lower timestamps get unblocked when the pushee bumps its timestamp. Is that not the case?

[aayushshah15]

It's not happening in that select loop in MaybeWaitForPush but I don't know if it is supposed to happen elsewhere in the code.

[andreimatei]

@nvanbenschoten what's the story with -^ ?
As you've recently showed me, the lock table unblocks lower readers when it finds out that a conflicting txn's timestamp has been pushed. But what about the txnWaitQueue? If a pushee's timestamps changes, is the txn at the head of the txnWaitQueue supposed to react to that? And is the info supposed to make it through the txnWaitQueue to all the lock tables everywhere?

[nvanbenschoten]

If the pushee's timestamp changes due to a push then yes, all txn's in the txnWaitQueue will react to it. The queue reacts to calls to OnTransactionUpdated, which triggers a broadcast to all pusher's here.

However, if the pushee gets bumped due to the closed timestamp or a timestamp cache while issuing one of its requests then no one in the txnWaitQueue will hear about this. We could potentially feed this information to the transaction record during txn heartbeats, but that still might be up to a second later.

And is the info supposed to make it through the txnWaitQueue to all the lock tables everywhere?

Yes, anyone waiting the the txnWaitQueue is also waiting at the head of a lock wait-queue in a lockTable. See this diagram. So if their push succeeds, they'll update the corresponding lock.

[nvanbenschoten]

We need to do something here for v20.2 and maybe consider backporting something to v20.1. I suggest the following:

1. Don't bump EndTxn requests up to the closed timestamp (option 3 from above). It turns out that this is already the case, so there's nothing to actually change here. In applyTimestampCache, we only bump the batch by the closed timestamp if it contains a request with the consultsTSCache flag. Since the introduction of CanCreateTxnRecord, EndTxn has no longer carried this flag.
2. Split EndTxn from the rest of its batch after 1 (or 2?) successful refreshes in the txnSpanRefresher. The idea here is that after a successful refresh, we want to make sure we make some forward progress with a batch of writes and an EndTxn. What we see in this issue is that because the EndTxn throws an error due to the closed timestamp bump (on the writes earlier in the batch), it prevents the writes earlier in the batch from ever succeeding. This means that they continue to be included in the batch and continue to hit the closed timestamp after each refresh. So the proposal is to issue the writes separately and let them succeeding before issuing the EndTxn. There is precedent for this – we do something similar, for similar but not identical reasons in the DistSender after a transaction has restarted at least once.

With these in place, the timeline of the offending query would look something like the following and we would avoid the indefinite starvation regardless of the closed timestamp duration:

1. read all rows: Batch{Scan, Scan, ...}
2. try to delete all rows and commit: Batch{Delete, Delete, ..., EndTxn}
3. first two steps take over 3s so batch is pushed to `now - 3s` and hits a retry error when evaluating its EndTxn
4. refresh @ now - 3s
5. retry Batch{Delete, Delete, ...}. Gets pushed but succeeds at higher timestamp
6. retry EndTxn, throws error during evaluation
7. refresh @ now - 3s
8. retry EndTxn, succeeds

Option 1 from above is also something we can consider, although we'd need to weigh its trade-offs.