Add support for deferred cutover

[kolbe]

Implements #244

The defer occurs before checksum. Documentation is included in this PR and makes it clear.

[morgo]

LGTM. I changed the timeout to 48 seconds for manual testing:

 go run . --host "127.0.0.1:8030" --defer-cutover
INFO[0000] Starting spirit migration: concurrency=4 target-chunk-size=500ms table=test.stock alter="engine=innodb"
INFO[0000] create BinlogSyncer with config {ServerID:1076 Flavor:mysql Host:127.0.0.1 Port:8030 User:msandbox Password: Localhost: Charset:utf8 SemiSyncEnabled:false RawModeEnabled:false TLSConfig:<nil> ParseTime:false TimestampStringLocation:UTC UseDecimal:false RecvBufferSize:0 HeartbeatPeriod:0s ReadTimeout:0s MaxReconnectAttempts:0 DisableRetrySync:false VerifyChecksum:false DumpCommandFlag:0 Option:<nil> Logger:0x14000110e60 Dialer:0x100b58580 RowsEventDecodeFunc:0x100d364a0 TableMapOptionalMetaDecodeFunc:<nil> DiscardGTIDSet:false EventCacheCount:10240}
WARN[0000] resuming from checkpoint. low-watermark: {"Key":["s_w_id","s_i_id"],"ChunkSize":56767,"LowerBound":{"Value": ["50","23955"],"Inclusive":true},"UpperBound":{"Value": ["50","80723"],"Inclusive":false}} log-file: binlog.005904 log-pos: 27728 copy-rows: 4999991
INFO[0000] skip dump, use last binlog replication pos (binlog.005904, 27728) or GTID set <nil>
INFO[0000] begin to sync binlog from position (binlog.005904, 27728)
INFO[0000] start sync binlog at binlog file (binlog.005904, 27728)
INFO[0000] copy rows complete
WARN[0000] cutover deferred while sentinel table test._stock_sentinel exists; will wait 48s
INFO[0030] migration status: state=waitingOnSentinelTable sentinel-table=test._stock_sentinel total-time=30s sentinel-wait-time=30s sentinel-max-wait-time=48s conns-in-use=0
INFO[0030] finished periodic flush of binary log: duration=4.801542ms
INFO[0048] closing canal
INFO[0048] syncer is closing...
INFO[0048] kill last connection id 62
INFO[0048] syncer is closed
spirit: error: timed out waiting for sentinel table to be dropped
exit status 1

It resumes fine, and responds quickly when the sentinel is dropped:

go run . --host "127.0.0.1:8030" --defer-cutover
INFO[0000] Starting spirit migration: concurrency=4 target-chunk-size=500ms table=test.stock alter="engine=innodb"
INFO[0000] create BinlogSyncer with config {ServerID:1392 Flavor:mysql Host:127.0.0.1 Port:8030 User:msandbox Password: Localhost: Charset:utf8 SemiSyncEnabled:false RawModeEnabled:false TLSConfig:<nil> ParseTime:false TimestampStringLocation:UTC UseDecimal:false RecvBufferSize:0 HeartbeatPeriod:0s ReadTimeout:0s MaxReconnectAttempts:0 DisableRetrySync:false VerifyChecksum:false DumpCommandFlag:0 Option:<nil> Logger:0x14000404b90 Dialer:0x100df0580 RowsEventDecodeFunc:0x100fce4a0 TableMapOptionalMetaDecodeFunc:<nil> DiscardGTIDSet:false EventCacheCount:10240}
WARN[0000] resuming from checkpoint. low-watermark: {"Key":["s_w_id","s_i_id"],"ChunkSize":56767,"LowerBound":{"Value": ["50","23955"],"Inclusive":true},"UpperBound":{"Value": ["50","80723"],"Inclusive":false}} log-file: binlog.005904 log-pos: 27728 copy-rows: 4999991
INFO[0000] skip dump, use last binlog replication pos (binlog.005904, 27728) or GTID set <nil>
INFO[0000] begin to sync binlog from position (binlog.005904, 27728)
INFO[0000] start sync binlog at binlog file (binlog.005904, 27728)
INFO[0000] copy rows complete
WARN[0000] cutover deferred while sentinel table test._stock_sentinel exists; will wait 48s
INFO[0030] migration status: state=waitingOnSentinelTable sentinel-table=test._stock_sentinel total-time=30s sentinel-wait-time=30s sentinel-max-wait-time=48s conns-in-use=2
INFO[0030] finished periodic flush of binary log: duration=986.292µs
INFO[0039] sentinel table dropped at 2023-11-27 14:01:23.270618 -0700 MST m=+39.130231834
INFO[0039] starting to flush changeset
INFO[0039] blocking until we have read all binary logs: current-pos=(binlog.005905, 511513946) target-pos=(binlog.005905, 511513730)
INFO[0039] Running ANALYZE TABLE
INFO[0039] blocking until we have read all binary logs: current-pos=(binlog.005905, 511514342) target-pos=(binlog.005905, 511514126)
INFO[0039] starting checksum operation, this will require a table lock
WARN[0039] trying to acquire table lock, timeout: 30
WARN[0039] table lock acquired
INFO[0039] blocking until we have read all binary logs: current-pos=(binlog.005905, 511514558) target-pos=(binlog.005905, 511514342)
INFO[0039] starting to flush changeset
INFO[0039] blocking until we have read all binary logs: current-pos=(binlog.005905, 511514774) target-pos=(binlog.005905, 511514558)
WARN[0039] table lock released
INFO[0039] table unlocked, starting checksum
INFO[0044] checksum passed
INFO[0044] starting to flush changeset
INFO[0044] blocking until we have read all binary logs: current-pos=(binlog.005905, 511514990) target-pos=(binlog.005905, 511514774)
INFO[0044] starting to flush changeset
INFO[0044] blocking until we have read all binary logs: current-pos=(binlog.005905, 511515419) target-pos=(binlog.005905, 511515203)
WARN[0044] Attempting final cut over operation (attempt 1/5)
INFO[0044] Using cutover algorithm: rename-under-lock
WARN[0044] trying to acquire table lock, timeout: 30
WARN[0044] table lock acquired
WARN[0044] table lock released
WARN[0044] final cut over operation complete
INFO[0044] successfully dropped old table
INFO[0044] apply complete: instant-ddl=false inplace-ddl=false total-chunks=45 copy-rows-time=0s checksum-time=5s total-time=44s conns-in-use=0
INFO[0044] closing canal
INFO[0044] syncer is closing...
INFO[0044] kill last connection id 70
INFO[0044] syncer is closed