Cut-over should wait for heartbeat lag to be low enough to succeed #921
Conversation
|
Another day passed by and we learned something new about this problem. I added details to the original issue #799 (comment) about how the Aurora setting My team are not convinced that it's safe for us to change the Aurora default value of |
|
I'm planning to look into this early next week. Thank you for the good writeup and followups! I don't have any Aurora feedback as I've never worked with Aurora. |
There was a problem hiding this comment.
While I don't own this repo, I'm curious to address this PR (also submitted as openark#14 downstream).
First, I'd like to point out that this PR and associated issue were presented so eloquently and with such detail that the review process was a pleasure. Hats off!
The issue/analysis/fix make perfect sense. This explains a lot, and Aurora users are not the only ones who have experienced this issue. Back at my previous workplace we were very aggressive about keeping replication lag low and so this wasn't something we saw.
Please see two suggestions inline on improving the logic at time of cut-over. Otherwise this is looking very good.
go/logic/migrator.go
Outdated
| heartbeatLag := this.migrationContext.TimeSinceLastHeartbeatOnChangelog() | ||
| maxLagMillisecondsThrottleThreshold := atomic.LoadInt64(&this.migrationContext.MaxLagMillisecondsThrottleThreshold) | ||
| if heartbeatLag > time.Duration(maxLagMillisecondsThrottleThreshold)*time.Millisecond { | ||
| this.migrationContext.Log.Debugf("current HeartbeatLag (%.2fs) is too high, it needs to be less than --max-lag-millis (%.2fs) to continue", heartbeatLag.Seconds(), (time.Duration(maxLagMillisecondsThrottleThreshold) * time.Millisecond).Seconds()) | ||
| return true, nil |
There was a problem hiding this comment.
Running two distinct sleepWhileTrue loops poses a problematic scenario where possibly the conditions tested in the first loop can re-appear while sleeping on the 2nd loop. I can imagine a user running a echo "postpone" | socat - "/tmp/gh-ost.sock" while sleeping on the newly introduced heartbeat lag loop.
My suggestion is to consolidate the two tests inside one loop, and I think it's simple: remove this new sleepWhileTrue and move the above five rows to be the fist condition tested in the original loop. Overall, there will be one sleepWhileTrue loop that'll look like this:
this.migrationContext.MarkPointOfInterest()
this.migrationContext.Log.Debugf("checking for cut-over postpone")
this.sleepWhileTrue(
func() (bool, error) {
heartbeatLag := this.migrationContext.TimeSinceLastHeartbeatOnChangelog()
maxLagMillisecondsThrottleThreshold := atomic.LoadInt64(&this.migrationContext.MaxLagMillisecondsThrottleThreshold)
if heartbeatLag > time.Duration(maxLagMillisecondsThrottleThreshold)*time.Millisecond {
this.migrationContext.Log.Debugf("current HeartbeatLag (%.2fs) is too high, it needs to be less than --max-lag-millis (%.2fs) to continue", heartbeatLag.Seconds(), (time.Duration(maxLagMillisecondsThrottleThreshold) * time.Millisecond).Seconds())
return true, nil
}
if this.migrationContext.PostponeCutOverFlagFile == "" {
return false, nil
}
if atomic.LoadInt64(&this.migrationContext.UserCommandedUnpostponeFlag) > 0 {
atomic.StoreInt64(&this.migrationContext.UserCommandedUnpostponeFlag, 0)
return false, nil
}
if base.FileExists(this.migrationContext.PostponeCutOverFlagFile) {
// Postpone file defined and exists!
if atomic.LoadInt64(&this.migrationContext.IsPostponingCutOver) == 0 {
if err := this.hooksExecutor.onBeginPostponed(); err != nil {
return true, err
}
}
atomic.StoreInt64(&this.migrationContext.IsPostponingCutOver, 1)
return true, nil
}
return false, nil
},
)
atomic.StoreInt64(&this.migrationContext.IsPostponingCutOver, 0)
this.migrationContext.MarkPointOfInterest()
this.migrationContext.Log.Debugf("checking for cut-over postpone: complete")what do you think?
There was a problem hiding this comment.
I'd possibly change:
if heartbeatLag > time.Duration(maxLagMillisecondsThrottleThreshold)*time.Millisecond {to
if heartbeatLag > time.Duration(base.CutOverLockTimeoutSeconds)*time.Second {It depends on whether a user's setting of maxLagMillisecondsThrottleThreshold is higher or lower than maxLagMillisecondsThrottleThreshold. In my previous use case, lag threshold was 1sec and cut-over timeout was 3sec, and it made more sense to initiate cut-over if lag was within bounds of 3sec.
Perhaps even the higher of the two values?
There was a problem hiding this comment.
Running two distinct sleepWhileTrue loops poses a problematic scenario where possibly the conditions tested in the first loop can re-appear while sleeping on the 2nd loop
I completely missed this, you are absolutely correct. I have pushed a commit Consolidate the two sleepWhileTrue loops to address this.
There was a problem hiding this comment.
In my previous use case, lag threshold was 1sec and cut-over timeout was 3sec, and it made more sense to initiate cut-over if lag was within bounds of 3sec.
Perhaps even the higher of the two values?
This makes a lot of sense to me, I think this is a good improvement. I have pushed a commit HeartbeatLag must be < than --max-lag-millis and --cut-over-lock-time to address this.
ccoffey
force-pushed
the
cathal/safer_cut_over
branch
from
f05baf2
to
3135a25
Compare
There was a problem hiding this comment.
LGTM.
Could you kindly also submit the recent commits to openark#14 ?
@timvaillancourt I do believe the issue may have happened (once) at GitHub, otherwise community has faced it multiple times. Seems like a popular fix!
Heh, that just happened automatically. Clearly I don't know how GitHub works 😜 |
Echoing this, great writeup @ccoffey 👍!
@shlomi-noach yes, this sounds familiar. This should make the cut-over more robust for many use cases 🎉!
Same here 😄 We can probably get this PR pushed to our automated testing replica this week. cc @rashiq |
I would love to learn more about this I ask because I am interested, and also because I am trying to figure out if I should wait before using my branch in production at my company 😉 |
@ccoffey we have dedicated replicas for testing The test case is much simpler than the CI testing that covers more of the functionality |
See https://github.blog/2017-07-06-mysql-testing-automation-at-github/ and https://speakerdeck.com/shlominoach/mysql-infrastructure-testing-automation-at-github |
|
@timvaillancourt any update on how the testing has been going? I see that this branch is now out of date, would you like me to rebase? |
|
I am pretty sure I have the same issue on GCP. Hopefully this will be merged soon. |
|
@ccoffey @zdannar in the meantime, and until this is merged, consider using this forked release: https://github.com/openark/gh-ost/releases/tag/v1.1.2 |
|
just used @shlomi-noach's fork to run a migration that wouldn't run with baseline gh-ost. Thank you so much!! |
|
@michaelglass that particular fix was contributed by @ccoffey |
|
@ccoffey / @shlomi-noach: apologies for the delay. We've recently cleared a backlog of integration testing This PR is now being tested on GitHub's testing replicas in #964 (required for testing) |
Description
Related issue: #799
In the above issue, we see migrations which fail at the cut-over phase with
ERROR Timeout while waiting for events up to lock. These migrations fail cut-over many times and eventually exhaust all retries.Root cause
Lag experienced by an external replica is not the same as lag experienced by gh-ost while processing the binlog.
show slave statusagainst an external replica and extracting the value ofSeconds_Behind_Master.For example: Imagine that both of these lags were ~0 seconds. Then imagine that you throttle gh-ost for N minutes. At this point the external replica's lag will still be ~0 seconds, but gh-ost's lag will be N minutes.
This is important because its gh-ost's lag (not the external replica's lag) that determines if cut-over succeeds or times out.
More Detail
During cut-over:
AllEventsUpToLockProcessed:time.Now()is inserted into the changelog table--cut-over-lock-timeout-seconds(default: 3 seconds) for this token to appear on the binlogProblem: It's possible to enter this cut-over phase when gh-ost is so far behind on processing the binlog that it could not possibly catch-up during the timeout.
What this PR proposes
CurrentHeartbeatLagin theMigrationContextCurrentHeartbeatLagevery time we intercept a binlog event for the changelog table of type heartbeatCurrentHeartbeatLagis less than--max-lag-millisNote: This PR is best-reviewed commit by commit
An example
It's best to demonstrate the value of this change by example.
I am able to reliably reproduce the cut-over problem (40+ failed cut-over attempts) when running gh-ost against an Amazon RDS Aurora DB.
Test setup:
Test process:
Both migrations are run using the following params:
Note:
<TABLE>and<UNIQUE_ID>must be different per migration.The following logs came from one of the many experiments I ran.
This log was output by the smaller of the two migrations when it got to
13.9%for row copy:Important: Notice that
Lagis0.01sbutHeartbeatLagis17.92s. The value ofLagis actually meaningless here because we are running with--allow-on-masterso we are computingLagby reading a heartbeat row directly from the table which we wrote it to. This explains the extremely low value of0.01s.A few minutes later, when row copy completed,
Lagwas0.01sandHeartbeatLagwas100.79s:This PR causes gh-ost to wait until the heartbeat lag is less than
--max-lag-millisbefore continuing with thecut-over.Note: If we had tried to cut-over during this period where
HeartbeatLagwas greater than100 secondsthen we would have failed many times.The heartbeat lag only started to reduce (a few minutes later) when the larger migration's row copy completed.
At this point the following message was outputted:
And then the table cut-over succeeded in a single attempt:
Final Thoughts
This problem is likely exacerbated by Aurora because readers in Aurora do not use binlog replication. This means there is no external replica lag that gh-ost can use to throttle itself so gh-ost ends up backing up the binlog. If gh-ost is the only consumer of the binlog (typical for applications that use Aurora) then only gh-ost's cut-over would suffer. Any observer looking at key health metrics on Aurora's dashboard would conclude that the DB was completely healthy.
The specific problem of backing up the binlog could be solved by getting gh-ost to copy rows much slower. However, gh-ost would still be susceptible to this problem in other ways, for example, if gh-ost was throttled heavily just before cut-over. Also, why should we artificially slow down if the DB is perfectly capable of handling the extra load without hurting our SLAs.