2019年5月21日火曜日

エラーログに MY-010956 と MY-010957 が出まくるはなし

TL;DR

  • MySQL 8.0同士でレプリケーションを組んでいると、スレーブから以下のような MY-010956MY-010957 がぼこぼこエラーログに吐かれることがある
2019-05-20T14:25:17.121864+09:00 5 [Warning] [MY-010956] [Server] Invalid replication timestamps: original commit timestamp is more recent than the immediate commit timestamp. This may be an issue if delayed replication is active. Make sure that servers have their clocks set to the correct time. No further message will be emitted until after timestamps become valid again.
2019-05-20T14:25:17.177804+09:00 5 [Warning] [MY-010957] [Server] The replication timestamps have returned to normal values.

日々の覚書: MySQL 8.0.1でバイナリーログに original_commit_timestamp と immediate_commit_timestamp が追加された という記事で書いたように、MySQL 8.0からはバイナリーログのイベントに(正確には、トランザクションがコミットされた時にイベントに先行して記録されるGtid_log_eventに)マイクロ秒単位でタイムスタンプが記録される。
このタイムスタンプが、 original_commit_timestamp > immediate_commit_timestamp (スレーブで実行されたタイムスタンプよりマスターで実行されたタイムスタンプが未来)になってしまった時にエラーログに記録されるワーニングが MY-010956MY-010956 が記録された後に original_commit_timestamp <= immediate_commit_timestamp に戻った時に記録されるワーニングが MY-010957
ところで、運用しているMySQLの載っているマシンが「マイクロ秒単位で」正しいシステムクロックに設定されていることに自信のある方はいらっしゃるだろうか?
俺には自信はない、というか、いいとこ1桁ミリ秒単位ならズレるだろうとも思っている。ホストとクロックを定期的に同期するVMならまだしも(試してない)、NTPではこのくらいの精度は限界なんではなかろうか。
というわけで、だ。
$ date "+%s.%N" ### at master
1558337325.766668654

$ date "+%s.%N" ### at slave
1558337325.767114036
こんな状況は起こりえる。500usマスターが進んでいる。
この状態でマスターに更新を叩き込んで、 “500us以内にそのバイナリーログの適用が終わった場合” に MY-010956 が発火する(適用に500us以上かかれば、再びスレーブのタイムスタンプがマスターのそれを追い越すので何も起こらない。これが出まくったってことはそれくらいのレイテンシーで更新できてるってことで望ましいことではある)
そして MY-010956 が発火して以降( MY-010956 は一度発火すると、次にタイムスタンプの順序が戻る= MY-010957 が出るまでは連続で発火しない)、 “適用に500us以上かかったバイナリーログのイベント” が来ると MY-010957 が着火し、次に500us未満で適用が終わったイベントが…と、延々発火し得る。
きっちり一致させられないにしろ、マスターのシステムクロックを進めればいいのでは? と思ったりしたけど、いつNTPでじりじりと補正されるかわからないし、マスターを切り替えちゃったらまた出ることには変わりはないし、だいたいmysqldを起動したまま手で時刻を修正するとか嫌な予感しかしない。
ワーニングだし「これはどう考えても出る時は出る」って感じなので無視するのがいいんだろうけれど、 log_error_verbosity を1(エラーのみロギング、ワーニング以下を無視する)にするのはちょっと大雑把かなと思うし、かといってエラーログはでっかくなるし。
閾値を設定できるようにしませんか? というFeature Requestがこれ。
いいな(?)と思ったら “Affects me” ください…

2019年5月16日木曜日

MySQL 8.0のSHOW TABLE STATUSが全然更新されない件

TL;DR


空っぽのテーブルを用意する。
mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2019-05-16 15:41:52
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
データを1万行くらい入れる。
$ for n in $(seq 1 10000) ; do mysql80 -e "INSERT INTO t1 VALUES ($n, '')" d1; done

mysql80 111566> SELECT COUNT(*) FROM t1;
+----------+
| COUNT(*) |
+----------+
|    10000 |
+----------+
1 row in set (0.00 sec)
でも SHOW TABLE STATUS の結果は変わらない。。
mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2019-05-16 15:41:52
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
ちなみに SHOW CREATE TABLE の方の AUTO_INCREMENT の値はちゃんと増えてる。
mysql80 111566> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=10001 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
これはMySQL 8.0.3から information_schema_stats_expiry なるオプションが増えてからの挙動で、どうも information_schema.tables に含まれるほとんどの情報は mysql.table_stats テーブルにキャッシュされ、そのキャッシュがexpireされるまではずっとその値を使う様子( mysql.table_stats は隠れシステムテーブルなので、フツーにSQLを使っているだけだとそのテーブルは見えない)
mysql80 111566> SELECT * FROM mysql.table_stats;
ERROR 3554 (HY000): Access to data dictionary table 'mysql.table_stats' is rejected.
オプションにも書いてある通り、単位は秒でデフォルトは86400秒(= 24時間)
つまりどれだけテーブルを更新しようと、 information_schema.tablesSHOW TABLE STATUS の値は「最後に mysql.table_stats が更新されてから24時間」は全く変更されない(ように見える)
コード的には このへん でキャッシュがexpireされてるかとかそのへんを判定してて、元をたどって進んでいくと ここらへん でキャッシュを更新する処理に突入している。
(現在時刻 - キャッシュの更新時刻) > information_schema_stats_expiryになった場合はキャッシュを更新してその結果を、 information_schema_stats_expiry = 0 の場合はそもそも mysql.table_stats テーブルをキャッシュとして 使わない みたいな動作になるようだ。
mysql80 111566> SET SESSION information_schema_stats_expiry= 1;
Query OK, 0 rows affected (0.01 sec)

mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 10000
 Avg_row_length: 32
    Data_length: 327680
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: 10001
    Create_time: 2019-05-16 15:41:52
    Update_time: 2019-05-16 16:02:34
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
セッションスコープ, グローバルスコープが両方あるタイプの変数なので、監視用のセッションにだけ押し込んでおけばいいかと。
しかし SET_VAR 構文は使えないらしいので残念。

2019年4月26日金曜日

MySQL 8.0.16にCHECK制約が来て、NOT ENFORCEDなんてものまでついてきた

TL;DR

  • MySQL 8.0.16 についに CHECK制約 が実装された
  • NOT ENFORCED なんてオプションが “MySQLっぽい”
  • ちなみにCHECK制約の追加はオンラインDDL不可、引っぺがすのはできる

最初のFeature Requestから15年、ついにMySQL 8.0.16にCHECK制約が実装された。
アルファベットしか入ってほしくない val カラムに対して、ひらがなの “さん” とかが入力されるのを制限できる、みたいなヤーツ。
フツーの遊び方は @taka_yuki_04 さんの記事に書いてある(というかドキュメントにも書いてある)ので、俺は「既存のテーブルにCHECK制約」ででも遊んでみる。
まず、こんなテーブルがあるじゃろ?
mysql80 8> SELECT @@version;
+-----------+
| @@version |
+-----------+
| 8.0.16    |
+-----------+
1 row in set (0.00 sec)

mysql80 8> CREATE TABLE t1 (num serial, val varchar(32));
Query OK, 0 rows affected (0.02 sec)

mysql80 8> INSERT INTO t1 VALUES (1, 'one'), (2, 'two'), (3, 'さん');
Query OK, 3 rows affected (0.01 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql80 8> SELECT * FROM t1;
+-----+--------+
| num | val    |
+-----+--------+
|   1 | one    |
|   2 | two    |
|   3 | さん   |
+-----+--------+
3 rows in set (0.00 sec)
val にアルファベット以外( val RLIKE '^[a-z]+$' を満たさない)を入れさせないようなCHECK制約をかけようとするじゃろ?
mysql80 8> ALTER TABLE t1 ADD CHECK(val RLIKE '^[a-z]+$');
ERROR 3819 (HY000): Check constraint 't1_chk_1' is violated.
既に制約違反しているから ALTER TABLE がエラーになるんじゃ。
という訳で制約に違反している行を消すじゃろ?
mysql80 8> DELETE FROM t1 WHERE num = 3;
Query OK, 1 row affected (0.00 sec)

mysql80 8> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | two  |
+-----+------+
2 rows in set (0.00 sec)
すると通るんじゃ。
mysql80 8> ALTER TABLE t1 ADD CHECK(val RLIKE '^[a-z]+$');
Query OK, 2 rows affected (0.03 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql80 8> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`),
  CONSTRAINT `t1_chk_1` CHECK (regexp_like(`val`,_utf8mb4'^[a-z]+$'))
) ENGINE=InnoDB AUTO_INCREMENT=4 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
CHECK制約があれば、 “さん” はそもそも入らないんじゃ。
mysql80 8> INSERT INTO t1 VALUES (3, 'さん');
ERROR 3819 (HY000): Check constraint 't1_chk_1' is violated.

mysql80 8> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | two  |
+-----+------+
2 rows in set (0.00 sec)
Σ(゚д゚lll) フツーのDBMSっぽい!
しかしまあ、MySQLっぽいと言われる謎の NOT ENFORCED なんて句がついてきて
mysql80 8> ALTER TABLE t1 DROP CHECK t1_chk_1;
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql80 8> ALTER TABLE t1 ADD CHECK(val RLIKE '^[a-z]+$') NOT ENFORCED;
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql80 8> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`),
  CONSTRAINT `t1_chk_1` CHECK (regexp_like(`val`,_utf8mb4'^[a-z]+$')) /*!80016 NOT ENFORCED */
) ENGINE=InnoDB AUTO_INCREMENT=4 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

mysql80 8> INSERT INTO t1 VALUES (3, 'さん');
Query OK, 1 row affected (0.01 sec)

mysql80 8> SELECT * FROM t1;
+-----+--------+
| num | val    |
+-----+--------+
|   1 | one    |
|   2 | two    |
|   3 | さん   |
+-----+--------+
3 rows in set (0.00 sec)
:(;゙゚’ω゚’): なんと入る
誰得なんだろう…せめてワーニングとか出てくれるといいんだけどな。。
ところで、 ALTER TABLE でCHECK制約を追加するということは、それってオンラインでできるの的な疑問が湧いてくるんですが、2019年4月25日 20時10分02秒 JST 現在、InnoDBのオンラインDDL関連のページにはCHECK制約については特に記載なし。
mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= INSTANT;
ERROR 1845 (0A000): ALGORITHM=INSTANT is not supported for this operation. Try ALGORITHM=COPY.

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= INPLACE;
ERROR 1845 (0A000): ALGORITHM=INPLACE is not supported for this operation. Try ALGORITHM=COPY.

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= COPY, LOCK= NONE;
ERROR 1846 (0A000): LOCK=NONE is not supported. Reason: COPY algorithm requires a lock. Try LOCK=SHARED.

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= COPY, LOCK= SHARED;
Query OK, 3 rows affected (0.04 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= COPY, LOCK= EXCLUSIVE;
Query OK, 3 rows affected (0.03 sec)
Records: 3  Duplicates: 0  Warnings: 0
試した感じ、 ALGORITHM= COPY (テーブルコピー)で LOCK= SHARED (共有ロック、読めるけど書けない)か LOCK = EXCLUSIVE (排他ロック、読めないし書けない)しか選べない模様。。
このへん、せめてINPLACEとかできるようになるといいな(いくら全行チェックが必要とはいえ、テーブルコピーする必要はないはず…)

2019年4月23日火曜日

MySQL 8.0.15現在、 SET PERSIST_ONLY にはあんまり手を出さない方が良いと思う

TL;DR

  • 手を出さない方がいいのはSET PERSIST_ONLYの話で、SET PERSISTは手を出してもいいと思う
  • SET GLOBAL, SET PERSIST には値をセットするためのバリデーター(各サーバー変数ごとにある)が用意されているが、 SET PERSIST_ONLY はそのバリデーターを通らないため、不正な値を突っ込んでもエラーになってくれない
  • mysqld を再起動しようとした時に、 mysqld-auto.cnfSET PERSIST, SET PERSIST_ONLY の保管先)に不正な値が突っ込んであるとそれを適用できなくて mysqld が起動してくれない

最初に見つけた時は innodb_ft_aux_table で見つけたのでそんなにアレじゃないかなと思ってたんだけれども、 SET GLOBAL, SET PERSIST には値をセットするためのバリデーター(各サーバー変数ごとにある)が用意されているが、 SET PERSIST_ONLY はそのバリデーターを通らないため、不正な値を突っ込んでもエラーになってくれない、という不具合を3月にレポートしていた。
数値型のやつに文字列型、みたいなやつはちゃんと弾いてくれる。

mysql80 8> SET PERSIST_ONLY max_connections= 'abc';

ERROR 1232 (42000): Incorrect argument type to variable 'max_connections'
問題になるのは、「文字列型を受け取るけどそれにもちゃんとルールがある」やつだ。
ばぐれぽ で使っている innodb_ft_aux_table は「フルテキストインデックスが存在するテーブル」を指定しなければならない。それ以外のテーブルを指定した場合はエラーになる。
mysql80 8> SHOW CREATE TABLE d1.t1\G -- フルテキストインデックスがない
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

mysql80 8> SET GLOBAL innodb_ft_aux_table = 'd1/t1';
ERROR 1231 (42000): Variable 'innodb_ft_aux_table' can't be set to the value of 'd1/t1'
SET PERSIST_ONLY はこれをすり抜けるので、次に mysqld を起動しようとした時にこの不正な値がキマって起動しなくなる。
mysql80 8> SET PERSIST_ONLY innodb_ft_aux_table = 'd1/t1';
Query OK, 0 rows affected (0.00 sec)

mysql80 8> SELECT * FROM performance_schema.persisted_variables;
+---------------------+----------------+
| VARIABLE_NAME       | VARIABLE_VALUE |
+---------------------+----------------+
| innodb_ft_aux_table | d1/t1          |
+---------------------+----------------+
1 row in set (0.01 sec)
ちなみに「間違った!」というのがわかるのであれば、 RESET PERSIST ステートメントでクリアできる。 mysqld を落とす前なら。
mysql80 8> RESET PERSIST innodb_ft_aux_table;
Query OK, 0 rows affected (0.00 sec)

mysql80 8> SELECT * FROM performance_schema.persisted_variables;
Empty set (0.00 sec)
話が厄介なのは、「ENUMなサーバー変数」で、コイツは「文字列でも数値でもセットできる」「本来正しい(?)値は文字列型」「数値を渡された時に文字列に変換しているのはどうやら変数セット時のバリデーター」というアレがあり、
mysql80 8> SELECT @@binlog_error_action;
+-----------------------+
| @@binlog_error_action |
+-----------------------+
| ABORT_SERVER          |
+-----------------------+
1 row in set (0.00 sec)

mysql80 8> SET GLOBAL binlog_error_action = 0; -- SET GLOBALで数値をセットするじゃろ?
Query OK, 0 rows affected (0.00 sec)

mysql80 8> SELECT @@binlog_error_action; -- ちゃんと文字列で表示されるじゃろ?
+-----------------------+
| @@binlog_error_action |
+-----------------------+
| IGNORE_ERROR          |
+-----------------------+
1 row in set (0.00 sec)
mysql80 8> SET PERSIST_ONLY binlog_error_action = 0; -- PERSIST_ONLYで数値をセットするじゃろ?
Query OK, 0 rows affected (0.00 sec)

mysql80 8> SELECT * FROM performance_schema.persisted_variables; -- 0のままじゃろ?
+---------------------+----------------+
| VARIABLE_NAME       | VARIABLE_VALUE |
+---------------------+----------------+
| binlog_error_action | 0              |
+---------------------+----------------+
1 row in set (0.00 sec)

mysql80 8> RESTART; -- キマるんじゃ
Query OK, 0 rows affected (0.01 sec)
エラーログはこんなんなりました。
無限にプロセスの起動失敗と再起動を繰り返しております(たぶん RESTART ステートメントじゃなくて systemctl restart mysqld とかだと綺麗に死んでくれるかな…わからん)
2019-04-23T08:29:56.321633Z 8 [System] [MY-011086] [Server] Received RESTART from user root.  Restarting mysqld (Version: 8.0.15).
..
2019-04-23T08:30:00.242090Z 0 [System] [MY-010910] [Server] /usr/mysql/8.0.15/bin/mysqld: Shutdown complete (mysqld 8.0.15)  Source di
stribution.
2019-04-23T08:30:00.388768Z mysqld_safe Number of processes running now: 0
2019-04-23T08:30:00.393888Z mysqld_safe mysqld restarted

..
2019-04-23T08:30:12.326063Z 5 [ERROR] [MY-011268] [Server] Configuring persisted options failed: "Variable 'binlog_error_action' can't
 be set to the value of '0'".
2019-04-23T08:30:12.326121Z 0 [ERROR] [MY-010175] [Server] Setting persistent options failed.
2019-04-23T08:30:12.440194Z mysqld_safe Number of processes running now: 0
2019-04-23T08:30:12.444490Z mysqld_safe mysqld restarted

..
2019-04-23T08:30:13.507286Z 5 [ERROR] [MY-011268] [Server] Configuring persisted options failed: "Variable 'binlog_error_action' can't
 be set to the value of '0'".
2019-04-23T08:30:13.507327Z 0 [ERROR] [MY-010175] [Server] Setting persistent options failed.
2019-04-23T08:30:13.633597Z mysqld_safe Number of processes running now: 0
2019-04-23T08:30:13.638389Z mysqld_safe mysqld restarted

..
2019-04-23T08:30:15.253603Z 5 [ERROR] [MY-011268] [Server] Configuring persisted options failed: "Variable 'binlog_error_action' can't
 be set to the value of '0'".
2019-04-23T08:30:15.253652Z 0 [ERROR] [MY-010175] [Server] Setting persistent options failed.
2019-04-23T08:30:15.364141Z mysqld_safe Number of processes running now: 0
2019-04-23T08:30:15.368649Z mysqld_safe mysqld restarted

..





2019年4月22日月曜日

gh-ostの最後のステップの `RENAME TABLE ..` を任意のタイミングまで遅延させる

TL;DR

  • --postpone-cut-over-flag-file でテキトーなファイルを指定する
  • RENAME TABLE .. (gh-ostの cut-over フェーズ)をしても良いタイミングになったら、「指定したファイルを消す」または 「 Interactive commandsunpostpone コマンドを放り込む」

gh-ost は起動してからよしなにバイナリーログを吸い上げてゴーストテーブル(スキーマに対する変更を適用しつつ、オリジナルのテーブルへの更新とオリジナルのテーブルからデータを少しずつフェッチしてマージしたもの)を作り、最後にはオリジナルのテーブルとゴーストテーブルを RENAME TABLE .. で入れ替えることでオンラインスキーマ変更を実現している。デフォルトでは用済みになったオリジナルのテーブルもドロップしない。
pt-online-schema-change がトリガーを仕掛けてゴーストテーブル(Percona Toolkitではそうは呼ばないけれど)を組み立てて、 RENAME TABLE .. をかけてトリガーも片付けて更に入れ替えて用済みになったオリジナルのテーブルに対して DROP TABLE までかけてくれる(デフォルト。しないようにもできる)のに比べれば、メタデータロックを取らないといけない操作も少ないし突然のLazy Drop Tableで死ぬことも少ないのだけれども。
それでも「その瞬間だけSELECTすらブロックするような」でかいロックを取る操作の前には心の準備として一拍置きたい気持ちがあったりなかったりする。
オリジナルのテーブルへのアクセスが十分少ない(人によって変わると思う)場合、pt-oscくらい何回もメタデータロックを取っていても全然問題なかったりする。なので別にこれがデフォルトになってほしいとは思わない(大概の場合、迷っているより流れちゃった方がさっさと済むのだ)
前置きが長くなったけど、やり方は TL;DR の通り。
$ gh-ost --database=d1 --table=t1 --alter="Engine = InnoDB" --port=64057 --user=root --host=127.0.0.1 --allow-on-master --execute --ok-to-drop-table --postpone-cut-over-flag-file=/tmp/moge
..
Copy: 0/2 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: bin.000014:566423; State: migrating; ETA: N/A
Copy: 0/2 0.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 1s(copy); streamer: bin.000014:570719; State: migrating; ETA: N/A
Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 1s(copy); streamer: bin.000014:571447; State: migrating; ETA: due
Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: bin.000014:575747; State: postponing cut-over; ETA: due
Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 3s(total), 1s(copy); streamer: bin.000014:580057; State: postponing cut-over; ETA: due
..
cut-overの遅延が有効になっている場合、ゴーストテーブルを組み立て終わった時点で State: postponing cut-over になる。
この状態ではもうオリジナルテーブルからのマージは終わっているから、ひたすらバイナリーログを吸い上げてはその差分を適用し続けるだけの状態。
$ ll /tmp/moge
-rwxr-xr-x 1 yoku0825 yoku0825 0 Apr 22 15:51 /tmp/moge

$ file /tmp/moge
/tmp/moge: empty
--postpone-cut-over-flag-file に渡したパスには空っぽのファイルが出来上がっていて、これを消すかInteractive commandsから unpostpone を放り込むとcut-overフェーズに突入する。
$ rm /tmp/moge

..
Copy: 2/2 100.0%; Applied: 0; Backlog: 1/1000; Time: 10s(total), 1s(copy); streamer: bin.000014:611206; State: migrating; ETA: due
# Migrating `d1`.`t1`; Ghost table is `d1`.`_t1_gho`
# Migrating 163-44-175-117:64057; inspecting 163-44-175-117:64057; executing on 163-44-175-117
# Migration started at Mon Apr 22 16:49:10 +0900 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# postpone-cut-over-flag-file: /tmp/moge
# Serving on unix socket: /tmp/gh-ost.d1.t1.sock
Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 10s(total), 1s(copy); streamer: bin.000014:611647; State: migrating; ETA: due
[2019/04/22 16:49:20] [info] binlogsyncer.go:164 syncer is closing...
[2019/04/22 16:49:21] [error] binlogstreamer.go:77 close sync with err: sync is been closing...
[2019/04/22 16:49:21] [info] binlogsyncer.go:179 syncer is closed
# Done
State: migrating になって、最後の処理である RENAME TABLE .. などが行われる。

ところで、この cut-over を遅延させるための(ファイルを指定する以外の)オプションだと思っていた --cut-over というのがあったんだけれど、こっちは何の関係もなかった。。
$ gh-ost .. --cut-over=two-step
..

2019-04-22T15:37:48.792707+09:00           40 Query     lock /* gh-ost */ tables `d1`.`t1` write
2019-04-22T15:37:49.793151+09:00           40 Query     alter /* gh-ost */ table `d1`.`t1` rename `_t1_del`
2019-04-22T15:37:49.798139+09:00           42 Query     alter /* gh-ost */ table `d1`.`_t1_gho` rename `t1`
2019-04-22T15:37:49.800834+09:00           40 Query     unlock /* gh-ost */ tables

$ gh-ost .. --cut-over=atomic
..

2019-04-22T16:49:19.941893+09:00           81 Query     select get_lock('gh-ost.81.lock', 0)
2019-04-22T16:49:19.949646+09:00           81 Query     lock /* gh-ost */ tables `d1`.`t1` write, `d1`.`_t1_del` write
2019-04-22T16:49:20.942595+09:00           87 Query     rename /* gh-ost */ table `d1`.`t1` to `d1`.`_t1_del`, `d1`.`_t1_gho` to `d1`.`t1`
2019-04-22T16:49:20.948139+09:00           81 Query     unlock tables
2019-04-22T16:49:21.039657+09:00           81 Quit
atomic (こっちがデフォルト)の方が良さそう。