MySQL5.7からMySQL5.6にレプリケーションしようとしたらBugを踏んだ話
ここ最近、紙の書籍から電子書籍に（いまさら）ほぼ完全に移ったのですが読書ペースが上がった気がします。 技術書って大きいサイズのものが多いので持ち運びにはなかなか向きませんが、タブレットなら何冊も同時に持ち運べて便利なんですよね。 小さめのタブレットだったら片手でも読めますし。 あとは出版業界全体がもう少し電子書籍に対応してくれればいいのにと思っています。
さて、今回はタイトル通りのお話です。 正直ケースが特殊すぎるし、いまさらMySQL5.6の話かよという感じですが・・・
やったことを3行で
- MySQL5.7からMySQL5.6へレプリケーションしようとしたら更新内容がなぜか5.6側に反映されない
- ググったらBugであることがわかった、ついでにソースコード上でどのように変更があったのか確認した
- mysqlbinlogのRオプションで擬似IOスレッドみたいなものを用意して有事の際はロールバックできるようにした
そもそもなんでMySQL5.7から5.6へレプリケーションしようとしたのかというと、担当サービスでMySQL5.6から5.7へのバージョンアップをすることになったのですが、もし何らかの理由でMySQL5.7から5.6に切り戻したいといった場合を考えると5.7から5.6へレプリケーションしたかったのです。
今回のケースではMySQL5.7.14およびMySQL5.6.17を使っていました。 なおGTIDは使わないポジションベースのレプリケーションを利用していました。
実際に起きたことのイメージ
slave_mysql56>CHANGE MASTER TO -> MASTER_HOST='TEST1', -> MASTER_PORT=3306, -> MASTER_LOG_FILE='binary_log.000338', -> MASTER_LOG_POS=3041684, -> MASTER_USER='repltest', -> MASTER_PASSWORD='repltest' slave_mysql56 >show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: TEST1 Master_User: repltest Master_Port: 3306 Connect_Retry: 60 Master_Log_File: binary_log.000338 Read_Master_Log_Pos: 3041510 Relay_Log_File: relay_log.000004 Relay_Log_Pos: 283 Relay_Master_Log_File: binary_log.000338 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 3041510 Relay_Log_Space: 446 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: 0 Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: Replicate_Ignore_Server_Ids: Master_Server_Id: 4472 Master_UUID: 0ef90e99-cec3-11e9-9ee5-ecf4bbe920ec Master_Info_File: mysql.slave_master_info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: Executed_Gtid_Set: Auto_Position: 0 1 row in set (0.00 sec) master_mysql57 >CREATE DATABASE repl_test; Query OK, 1 row affected (0.00 sec) master_mysql57 >USE repl_test; master_mysql57 >CREATE TABLE t1(a int); Query OK, 0 rows affected (0.00 sec) master_mysql57 >INSERT INTO t1 VALUES (1), (2), (3); Query OK, 3 rows affected (0.00 sec) Records: 3 Duplicates: 0 Warnings: 0 master_mysql57 >SELECT count(*) FROM t1; +----------+ | count(*) | +----------+ | 3 | +----------+ 1 row in set (0.00 sec) slave_mysql56 >USE repl_test Database changed slave_mysql56 >SELECT count(*) FROM t1; ERROR 1146 (42S02): Table 'repl_test.t1' doesn't exist slave_mysql56 >SHOW TABLES; Empty set (0.00 sec) slave_mysql56 >show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: TEST1 Master_User: repltest Master_Port: 3306 Connect_Retry: 60 Master_Log_File: binary_log.000338 Read_Master_Log_Pos: 3042808 Relay_Log_File: relay_log.000004 Relay_Log_Pos: 932 Relay_Master_Log_File: binary_log.000338 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 3042808 Relay_Log_Space: 1095 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: 0 Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: Replicate_Ignore_Server_Ids: Master_Server_Id: 4472 Master_UUID: 0ef90e99-cec3-11e9-9ee5-ecf4bbe920ec Master_Info_File: mysql.slave_master_info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: Executed_Gtid_Set: 00000000-0000-0000-0000-000000000000:0 Auto_Position: 0
とこのようにMySQL5.7側で行った変更が5.6では反映されません。
さらにGTIDを利用していないのにもかかわらず2回目のshow slave statusのExecuted_Gtid_Setに00000000-0000-0000-0000-000000000000:0となるGTIDがセットされていることがわかりました。
しかも最初の更新であるCREATE DATABASE repl_testはしっかり反映されています。(Slave側でUSEできることからわかります)
いろいろ調べてみたところ次のBug reportを発見しました。
MySQL Bugs: #75772: 5.7.6->5.6 replication fails
ふむふむ、これを見るところMySQL5.7.6以降のサーバからMySQL5.6.23以前のサーバにレプリケーションするときに、古いApplierスレッドがAnonymous_gtid_log_eventを検出した場合アサートを引き起こすとのことです。
GTIDが無効である場合、ApplierスレッドがGtid_log_eventを検出してしまい終了する。GTIDが有効である場合、ApplierスレッドがAnonymous_gtid_log_eventを検出して終了する。
つまりGTIDモードの有効/無効に関わらず該当のバージョン間ではレプリケーションができないということです。
で、何でAnonymous_gtid_log_eventが検出されるのよ
これについてはリファレンスと下記スライドを参考させていただきました。
MySQL :: MySQL 5.7 Reference Manual :: 16.1.5.1 Replication Mode Concepts
Transactions in a relay log that was received from a master running a previous version of MySQL may not be preceded by any particular event at all, but after being replayed and logged in the slave's binary log, they are preceded with an Anonymous_gtid_log_event.
Masterからの変更をSlaveで再生して、binary logに記録するときにAnonymous_gtid_log_eventが出力されるということでしょうか。
1回目のCREATE DATABASE repl_testがSlaveに反映された理由もこれでわかりました。1回目はGTIDが空なので問題なくリプレイできましたが、この変更によってAnonymous_gtid_log_eventがセットされてしまったため以降の変更は一切反映されなかったわけですね。
MySQL5.7 GA の Multi-threaded slave
また、MySQL5.7.6以降からGTID_MODE=OFFでもAnonymous_gtid_log_eventを出力しますが、それはオンラインでGTID_MODEを変更するための施策のようです。
対策を取らなくては
理由はわかったので次はどのように対策を練るか考えるべきです。
一番いいのはMySQL5.6を5.6.24以降のバージョンにバージョンアップすることだと思いますが、今回は次の理由で別の方法を取りました。
- 理由1 ロールバックする可能性が極めて低くバージョンアップする手間を考えるとバージョンアップするメリットがなかった
- 理由2 最悪の場合ロールバックする必要はあるが、古いサーバ側に常に最新の状態を反映させる必要はなかった
そもそもHWスペックはほぼ同じもしくは多少向上している、かつアプリ側で大規模な変更があったわけではないということからMySQL5.7で致命的な問題が起きてMySQL5.6に切り戻ししなくてはいけない状況というものがほとんど考えられなかったのです。
mysqlbinlogでMasterのbinary logをバックアップしよう
対策を考えていくうちにMaster側で行われた変更を古いサーバに適用させる(つまり、binary logのリプレイです)ことは問題なく実行できることがわかりました。(注意 僕の場合は問題ありませんでしたが、中には5.6ではエラーとなる内容も含まれる可能性はあります)
ただしレプリケーションは正しく行えないのでbinary logを別の方法でMasterサーバから引っ張ってくる必要がありますが・・・定期的にscpで持ってきたりというのはちょっと面倒だなと思っていました。
そこでmysqlbinlogの--read-from-remote-server(短縮形は-R)を使うことにしました。
MySQL :: MySQL 5.7 Reference Manual :: 4.6.7.3 Using mysqlbinlog to Back Up Binary Log Files
詳細は割愛しますが、このオプション+αを使うとリモートサーバのbinary log をバックアップすることができます。 つまり擬似的にレプリケーションにおけるIOスレッドを実現できるということです。（ただし本物のIOスレッドのようにMasterから変更を受け取ってそれをRelay logに書き込むことはしません）
実際には次のようなオプションを利用しました。
nohup mysqlbinlog -R --host=master_host --port=master_port --user=repltest --password=repl --stop-never --raw --result-file=recovery- binary_log.XXXXXX &
--stop-neverオプションはプロセスをKILLするまでbinary-logを読むオプション(tail -fのように)
--rawオプションは取得先のサーバと同じファイル名かつバイナリでファイルをバックアップする
--result-fileオプションは--rawオプションと一緒に使うことでバックアップファイル名にprefixをつけることができるオプションです。
ちなみにmysqlbinlogを使ってbinary logのバックアップを取るときは、Masterから見るとSlaveがもう1つ増えたような感じになります。
これでbinary logを持ってくることはできたので、あとはそれを適宜リプレイしてあげれば万事解決です。（つまりSQLスレッドの役割を行うということです）
今回は簡単なシェルスクリプト+cronで定期的にbinary logのリプレイをするようにしました。上述したとおり完璧に同期が取れている必要はないので数時間おきとかにbinary logをリプレイさせておきました。そこまで更新が激しいサービスではないのでそれでも十分でした。
というわけで今回はレプリケーション関連でBugを踏んだわけですが、MySQLのいいところの1つは調べれば誰かしら似たような状況に遭遇していて解決策がわかるということだと改めて思いました。
