VReplication: Improve handling of vplayer stalls

[mattlord]

Description

Please see the issue for details about the problems we're attempting to solve/improve in this PR.

The improvements here are about detecting when we're not making any progress and showing/logging meaningful errors to replace the eventual generic EOF errors.

There are two types of stalls that we now detect and error on:

1. Being unable to record heartbeats in the stream
   • This is a simple check and always enabled
2. Being unable to complete/commit a transaction consisting of replicated user events, which includes updating the vreplication record to record the latest position upon commit
   • This is disabled by default via the new flag to control the timeout defaulting to 0s. This is a more complicated check and given that the scenario that we're improving is, to the best of my knowledge, very rare I did not want to potentially introduce new edge cases by default (especially since the heartbeat change should catch many of them).

Related Issue(s)

• Fixes: Bug Report: VPlayer does not detect stalls #15974

Checklist

• "Backport to:" labels have been added if this change should be back-ported to release branches
• If this change is to be back-ported to previous releases, a justification is included in the PR description
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on CI?
• Documentation was added or is not required

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[codecov]

Codecov Report

Attention: Patch coverage is 64.28571% with 5 lines in your changes are missing coverage. Please review.

Project coverage is 68.23%. Comparing base (3b09eb2) to head (c666b14).
Report is 20 commits behind head on main.

Files	Patch %	Lines
.../vt/vttablet/tabletmanager/vreplication/vplayer.go	64.28%	5 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #15797      +/-   ##
==========================================
- Coverage   68.47%   68.23%   -0.25%     
==========================================
  Files        1562     1541      -21     
  Lines      197083   197127      +44     
==========================================
- Hits       134962   134517     -445     
- Misses      62121    62610     +489     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[mattlord]

• Instead of a tablet level flag, what do you think about adding a workflow option (in the new json object). That way we can allow it to be updated using WorkflowUpdate and it can be dynamically set/reset if required when the vplayer restarts and loads the settings?

That's a good idea! With the new json field that will be much simpler and I like that better.

@rohit-nayak-ps I started on that work here: 7b5c4c5

There will still be more work to do, so I will let you know when it's ready for another review. Until then, you can see where I'm going if you like and let me know if you perhaps changed your mind (it's certainly much more involved this way, but I do think it's better overall).

[mattlord]

• Instead of a tablet level flag, what do you think about adding a workflow option (in the new json object). That way we can allow it to be updated using WorkflowUpdate and it can be dynamically set/reset if required when the vplayer restarts and loads the settings?

That's a good idea! With the new json field that will be much simpler and I like that better.

@rohit-nayak-ps after spending quite a bit of time on it, I ended up reverting the work: b060e09

There was still more work to do there, and in working on it, it became more clear to me that this really is a vplayer component setting rather than a workflow option. So passing a duration all the way through from client flags, for each type of stream, just to configure the vplayer on the tablet, seemed like a lot of work today and into the future — any command that does use a vplayer that we want to be able to configure this would need to have it too, e.g. OnlineDDL and ApplySchema also need them today as the original issue seen was with OnlineDDL. In such I think it makes sense for it to be a vttablet flag. If you feel strongly about it, however, I can pick that work back up. It was nearly to the point where you could set it, view it, and update it in the various client commands. From there we just need to read and unmarshal the value from the _vt.vreplication record in the vreplication engine and thread it through the controller, vreplicator, and vplayer.

[mattlord]

@rohit-nayak-ps I could also just remove the transaction duration (stallHandler) part and stick with the simpler heartbeat based check. I do believe that will still be able to catch all of the cases, including the one seen in the original production issue. In that case the position was not getting updated via the replicated transaction or the heartbeat recording, so we should still have gotten the stalled vttablet log and the issue noted in the workflow's message field.

In any event, I did another test with the latest state:

❯ grep "stall handler" /opt/vtdataroot/tmp/*
...
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.532924   12895 vplayer.go:897] StallHandler-2527617803385045679: After stopping the stall handler goroutine for 15s, total: 422, active: 0 -- totalStallHandlerCount: 36
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.537210   12895 vplayer.go:878] StallHandler-2527617803385045679: Resetting the stall handler timer to 15s
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.537223   12895 vplayer.go:893] StallHandler-2527617803385045679: Starting the stall handler goroutine for 15s, total: 423, active: 1, totalStallHandlerCount: 36
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.537449   12895 vplayer.go:878] StallHandler-2527617803385045679: Resetting the stall handler timer to 15s
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.537781   12895 vplayer.go:917] StallHandler-2527617803385045679: Stopping the stall handler timer
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.537791   12895 vplayer.go:905] StallHandler-2527617803385045679: the stall handler timer was stopped
/opt/vtdataroot/tmp/vttablet.pslord.matt.log.INFO.20240525-023958.12895:I0525 02:40:27.537793   12895 vplayer.go:897] StallHandler-2527617803385045679: After stopping the stall handler goroutine for 15s, total: 423, active: 0 -- totalStallHandlerCount: 36

[rohit-nayak-ps]

@rohit-nayak-ps I could also just remove the transaction duration (stallHandler) part and stick with the simpler heartbeat based check.

This might indeed be a good path to choose, since your other change is catching the known issues.

Also while goroutines are lightweight, generating goroutines for every transaction could also lead to unpredictable performance impacts due to garbage collection, memory usage, scheduling issues etc especially since we will be enabling it in a high-qps situation.

[mattlord]

@rohit-nayak-ps I could also just remove the transaction duration (stallHandler) part and stick with the simpler heartbeat based check.

This might indeed be a good path to choose, since your other change is catching the known issues.

Also while goroutines are lightweight, generating goroutines for every transaction could also lead to unpredictable performance impacts due to garbage collection, memory usage, scheduling issues etc especially since we will be enabling it in a high-qps situation.

@rohit-nayak-ps Having more than 1 active/concurrent goroutine per vplayer/stallHandler was a bug. The intention was for this to be a lock-free idempotent stall handler that was very difficult to mess up — precisely because it's a high QPS component with a somewhat awkward way of managing the transactions so you may do multiple BEGINs before a COMMIT e.g. There should only ever be 0 or 1 goroutines active/running per vplayer/stallHander instance. After spending so much time on the investigation/testing/debugging part of the work I was a bit too eager to mark this as ready for review once my manual test and the new unit test were passing. That was sloppy on my part — I missed the bug in my self review and I clearly didn't have adequate testing, I apologize. Your thorough review was much appreciated though as you caught it. ❤️

I've added comments and a new unit test that demonstrate it now working as intended: 3839e90

I wanted to get it working so that even if I do end up discarding it here we'll still have it in the PR history if we ever want to revive it or reuse it for something else.

With all that being said, let me know what you think. I'm fine removing it for now since it was only well into my testing and debugging that I realized the existing heartbeat mechanism combined with the vreplicationMinimumHeartbeatUpdateInterval flag/variable were already supposed to effectively be serving the role of detecting stalls. The problem was a bug in that handling where we cleared the pending heartbeat counter before we were successfully able to save/record the heartbeat (we assumed it would be immediately successful). So now that I'm well aware of it and have also confirmed that mechanism is working as it should (it's used in the ROW based test case in the new TestPlayerStalls unit test) I think that the stallHandler mechanism is at least largely redundant. If I'm being honest, the main reason I would not want to delete it is that I spent some time on it. 🙂 That's obviously not a great reason to keep it and now that it's working and saved somewhere (commit history here), I'm totally fine removing it if you and others prefer it. Thanks again!

[shlomi-noach]

I think that the stallHandler mechanism is at least largely redundant. If I'm being honest, the main reason I would not want to delete it is that I spent some time on it.

@mattlord now that's it's been said, it cannot be unsaid... :)
Looking at the PR changes, the stall handler takes a considerable part of the actual logic changes. So I'd be curious to see a solution where the stall handler does not exist.

[mattlord]

@rohit-nayak-ps and @shlomi-noach this removes all of the stallHandler related code: c666b14

What we lose w/o it is the ability to perform out-of-band monitoring and errors. Meaning that the heartbeat method will only detect a stall when it was due to a failure to commit the transaction which updates the timestamp for the workflow (whether it was done on its own or as part of replicating user generated events).

If you both prefer that then I'll update the PR description accordingly. Thanks!

[shlomi-noach]

@mattlord thank you, I think we should go with this change, seeing that it's so succinct.

[rohit-nayak-ps]

@mattlord thank you, I think we should go with this change, seeing that it's so succinct.

Same here. Thanks @mattlord.