Skip to content

Commit 3fbb4d2

Browse files
committed
perf(cutover): drop two 1s sleeps from the locked cut-over window
Both sleeps happened while the original table was write-locked, so they were pure table downtime: - executeWriteFuncs slept 1s whenever both queues were empty, which is the steady state once row copy is done. The cut-over sentinel arrives on applyEventsQueue and had to wait that sleep out. It now blocks on both queues with a 1s timeout instead. - waitForRename watched for the blocking RENAME through retryOperation, which backs off a flat 1s. The first check usually runs before the RENAME shows up. It now checks every 10ms, via a new retryOperationWithInterval (retryOperation with the attempt count and wait made explicit). "Lock & rename duration" over the 73 localtests that reach cut-over. Before, it was ~1s on essentially every cut-over: mariadb:11.8 p50 9ms p90 21ms p99 90ms max 90ms mysql:8.4.3 p50 23ms p90 31ms p99 96ms max 96ms The tail is not this code path. It is waitForEventsUpToLock: on both flavours the same four cases, which happen to see no DML during the migration, spend 54-77ms waiting for the sentinel to come back through an otherwise idle binlog stream. No case with concurrent DML exceeds 50ms. That delay reproduces with a plain binlog reader, so it is in binlog delivery, not in gh-ost. TestCutOverLossDataCaseLockGhostBeforeRename now locks the ghost table before un-postponing, instead of relying on cut-over being slow. Fixes #1630
1 parent f7a42f6 commit 3fbb4d2

2 files changed

Lines changed: 51 additions & 19 deletions

File tree

go/logic/migrator.go

Lines changed: 40 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -165,13 +165,18 @@ func (mgtr *Migrator) retryBatchCopyWithHooks(operation func() error, notFatalHi
165165
// retryOperation attempts up to `count` attempts at running given function,
166166
// exiting as soon as it returns with non-error.
167167
func (mgtr *Migrator) retryOperation(operation func() error, notFatalHint ...bool) (err error) {
168-
maxRetries := int(mgtr.migrationContext.MaxRetries())
169-
for i := 0; i < maxRetries; i++ {
168+
return mgtr.retryOperationWithInterval(operation, int(mgtr.migrationContext.MaxRetries()), time.Second, notFatalHint...)
169+
}
170+
171+
// retryOperationWithInterval is `retryOperation` with an explicit attempt count and
172+
// wait between attempts. Callers that run while tables are locked use a sub-second
173+
// interval, where the default 1s wait would be pure table downtime.
174+
func (mgtr *Migrator) retryOperationWithInterval(operation func() error, attempts int, interval time.Duration, notFatalHint ...bool) (err error) {
175+
for i := 0; i < attempts; i++ {
170176
if i != 0 {
171177
// sleep after previous iteration
172-
sleepDuration := 1 * time.Second
173-
metrics.RecordSleep(mgtr.migrationContext.Metrics, "retry_backoff", sleepDuration)
174-
RetrySleepFn(sleepDuration)
178+
metrics.RecordSleep(mgtr.migrationContext.Metrics, "retry_backoff", interval)
179+
RetrySleepFn(interval)
175180
}
176181
// Check for abort/context cancellation before each retry
177182
if abortErr := mgtr.checkAbort(); abortErr != nil {
@@ -1119,8 +1124,21 @@ func (mgtr *Migrator) atomicCutOver() (err error) {
11191124
}
11201125
return mgtr.applier.ExpectProcess(renameSessionId, "metadata lock", "rename")
11211126
}
1122-
// Wait for the RENAME to appear in PROCESSLIST
1123-
if err := mgtr.retryOperation(waitForRename, true); err != nil {
1127+
// Wait for the RENAME to appear in PROCESSLIST. The first poll usually loses the
1128+
// race against the RENAME registering its metadata-lock wait, and this runs with
1129+
// the original table write-locked -- so poll fast rather than paying
1130+
// retryOperation's flat 1s backoff in table downtime. What we wait on is a
1131+
// statement starting on an already-open connection: a round-trip, not seconds.
1132+
//
1133+
// The RENAME runs with lock_wait_timeout=CutOverLockTimeoutSeconds (see
1134+
// Applier.AtomicCutoverRename), so past that it has errored out and set
1135+
// tableRenameKnownToHaveFailed -- at which point waitForRename returns
1136+
// immediately. Budget twice that, so the flag always wins and running out of
1137+
// attempts is unreachable in practice.
1138+
const renamePollInterval = 10 * time.Millisecond
1139+
renameWaitTimeout := 2 * time.Duration(mgtr.migrationContext.CutOverLockTimeoutSeconds) * time.Second
1140+
renamePollAttempts := int(renameWaitTimeout / renamePollInterval)
1141+
if err := mgtr.retryOperationWithInterval(waitForRename, renamePollAttempts, renamePollInterval, true); err != nil {
11241142
metrics.RecordCutOverPhase(mgtr.migrationContext.Metrics, metrics.CutOverPhaseMagicRename, time.Since(phaseStartTime), err)
11251143
// Abort! Release the lock
11261144
okToUnlockTable <- true
@@ -1936,7 +1954,18 @@ func (mgtr *Migrator) executeWriteFuncs() error {
19361954
}
19371955
default:
19381956
{
1957+
// Nothing was immediately available on the events queue. Block until one
1958+
// of the queues has work instead of sleeping a fixed second: during
1959+
// cut-over the AllEventsUpToLockProcessed sentinel arrives on
1960+
// applyEventsQueue while the tables are locked, and an unconditional
1961+
// sleep adds up to a full second of lock time (issue #1630).
19391962
select {
1963+
case eventStruct := <-mgtr.applyEventsQueue:
1964+
{
1965+
if err := mgtr.onApplyEventStruct(eventStruct); err != nil {
1966+
return err
1967+
}
1968+
}
19401969
case copyRowsFunc := <-mgtr.copyRowsQueue:
19411970
{
19421971
copyRowsStartTime := time.Now()
@@ -1956,12 +1985,11 @@ func (mgtr *Migrator) executeWriteFuncs() error {
19561985
}
19571986
}
19581987
}
1959-
default:
1988+
case <-time.After(time.Second):
19601989
{
1961-
// Hmmmmm... nothing in the queue; no events, but also no row copy.
1962-
// This is possible upon load. Let's just sleep it over.
1963-
mgtr.migrationContext.Log.Debugf("Getting nothing in the write queue. Sleeping...")
1964-
time.Sleep(time.Second)
1990+
// Nothing in the queue; no events, but also no row copy.
1991+
// Loop around to re-check abort/throttle state.
1992+
mgtr.migrationContext.Log.Debugf("Getting nothing in the write queue. Waiting...")
19651993
}
19661994
}
19671995
}

go/logic/migrator_test.go

Lines changed: 11 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1250,19 +1250,23 @@ func (suite *MigratorTestSuite) TestCutOverLossDataCaseLockGhostBeforeRename() {
12501250
}()
12511251

12521252
time.Sleep(2 * time.Second)
1253-
//nolint:dogsled
1254-
_, filename, _, _ := runtime.Caller(0)
1255-
err = os.Remove(filepath.Join(filepath.Dir(filename), "../../tmp/ghost.postpone.flag"))
1256-
if err != nil {
1257-
suite.Require().NoError(err)
1258-
}
1259-
time.Sleep(1 * time.Second)
1253+
1254+
// Hold a read lock on the ghost table *before* un-postponing: cut-over completes
1255+
// in milliseconds, so grabbing the lock after the flag removal is a race.
12601256
go func() {
12611257
holdConn, err := suite.db.Conn(ctx)
12621258
suite.Require().NoError(err)
12631259
_, err = holdConn.ExecContext(ctx, "SELECT *, sleep(2) FROM test._testing_gho WHERE id = 1")
12641260
suite.Require().NoError(err)
12651261
}()
1262+
time.Sleep(200 * time.Millisecond)
1263+
1264+
//nolint:dogsled
1265+
_, filename, _, _ := runtime.Caller(0)
1266+
err = os.Remove(filepath.Join(filepath.Dir(filename), "../../tmp/ghost.postpone.flag"))
1267+
if err != nil {
1268+
suite.Require().NoError(err)
1269+
}
12661270

12671271
dmlConn, err := suite.db.Conn(ctx)
12681272
suite.Require().NoError(err)

0 commit comments

Comments
 (0)