where句なしでupdate文を実行するというオペミスがあった際にdummyのrelay_log(binlogをrenameしたもの)を使って、1ホスト単体でMTSを利用した一人replication的なことをしてPITRする方法の検証をしてみた。
何いってんだと思ったら下のlefredの発表資料を見てみてください。
その過程でいくつかの疑問が出てきたので、そこまでを書いていく。
↓の発言に至った経緯と思ってもらえると良いです。
stopポジションとして指定したクエリまで、
— :tom__bo: (@tom__bo) 2019年1月17日
mysqlbinlog -> 実行しない
stop slave sql_thread until (file and pos)... -> 実行する(beginをまたいだ場合そのトランザクションごと実行??)
MySQL 5.7.17, GTID=OFFでの検証。
FOSDEM MySQL & Friends Devroom, February 2018 MySQL Point-in-Time Recovery like a Rockstar from Frederic Descamps
www.slideshare.net
(twitter profによると)MySQL Community Managerであるlefredさんの去年末の発表資料。これをやりたい。ロックスターらしいやり方だそう。
このやり方は公式ドキュメントの5.6の日本語版にのみあるという隠し機能と言っても過言でない代物。
(英語版の公式で削除されたのがjpでは追いついていないという話だと思う。)
https://dev.mysql.com/doc/refman/5.6/ja/change-master-to.html
去年のアドベントカレンダーでも id:hidemifukamachi さんもGTIDでの実験をされている
実験
1秒に一度insertをしている最中にupdate (where句なし)をしてそのクエリの直前までをPITRする。 このとき普通なら(Master - Slaveによる2台以上の構成なら)replicationを使って問題のクエリの直前までのrecoveryをやるだろうけど、今回はロックスターらしい方法を試したいのでそれでやる。
普通の方法はここでは説明しない。
table definition
>show create table t1\G *************************** 1. row *************************** Table: t1 Create Table: CREATE TABLE `t1` ( `id` int(11) NOT NULL AUTO_INCREMENT, `c1` int(11) DEFAULT NULL, PRIMARY KEY (`id`) ) ENGINE=InnoDB AUTO_INCREMENT=8 DEFAULT CHARSET=utf8 1 row in set (0.00 sec)
> select * from t1; +----+------+ | id | c1 | +----+------+ | 1 | 1 | | 2 | 2 | | 3 | 3 | | 4 | 4 | | 5 | 5 | | 6 | 6 | | 7 | 7 | +----+------+ 7 rows in set (0.00 sec)
queries
update.shで1秒ごとにinsert
#!/bin/sh for i in `seq 1 50`; do mysql -u tombo -ptombo d1 -e "insert into t1 (c1) values (${i});" sleep 1 done
この途中でオペミス(where句なしのupdate)を実行
update t1 set c1 = 0;
実験手順
- update.sh実行(50秒間、1秒ごとにinsert)
- オペミス
update t1 set c1 = 0; - 引き続きupdate.shのinsertが入る
- テーブルの状態確認
- binlogからポジションの特定
- binlogポジションまでのリカバリ
- テーブルの状態確認
実践
- update.sh実行(50秒間、1秒ごとにinsert)
- オペミス
update t1 set c1 = 0; - 引き続きupdate.shのinsertが入る
- 長いので5くらいで停止
- テーブルの状態確認
root@localhost:d1 16:29:27>select * from t1; +----+------+ | id | c1 | +----+------+ | 1 | 0 | | 2 | 0 | ... 省略 ... | 15 | 0 | | 16 | 9 | | 17 | 10 | | 18 | 11 | ... 省略 ... | 21 | 14 | +----+------+ 21 rows in set (0.00 sec)
- binlogからポジションの特定
オペミスのクエリはわかっている想定。
mysqlbinlog --no-defaults --base64-output=DECODE-ROWS -vv binary_log.000007 | less
# at 7307 #190118 0:54:02 server id 176200852 end_log_pos 7382 CRC32 0xc2dcde11 Query thread_id=225 exec_time =0 error_code=0 SET TIMESTAMP=1547740442/*!*/; BEGIN /*!*/; # at 7382 # at 7414 #190118 0:54:02 server id 176200852 end_log_pos 7414 CRC32 0x3b5cb298 Intvar SET INSERT_ID=15/*!*/; #190118 0:54:02 server id 176200852 end_log_pos 7514 CRC32 0xe86d806d Query thread_id=225 exec_time =0 error_code=0 SET TIMESTAMP=1547740442/*!*/; insert into t1 (c1) values (8) /*!*/; # at 7514 #190118 0:54:02 server id 176200852 end_log_pos 7545 CRC32 0x820ed923 Xid = 2634 COMMIT/*!*/; # at 7545 #190118 0:54:02 server id 176200852 end_log_pos 7610 CRC32 0xa9a360dc Anonymous_GTID last_committed=21 sequence_number=22 SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/; # at 7610 #190118 0:54:02 server id 176200852 end_log_pos 7685 CRC32 0xc95b8674 Query thread_id=12 exec_time =0 error_code=0 SET TIMESTAMP=1547740442/*!*/; BEGIN /*!*/; # at 7685 #190118 0:54:02 server id 176200852 end_log_pos 7775 CRC32 0xa0d818d7 Query thread_id=12 exec_time =0 error_code=0 SET TIMESTAMP=1547740442/*!*/; update t1 set c1 = 0 #### <<<<-------------------- here -----------!!!!!!!!!!!!!!!!!! /*!*/; # at 7775 #190118 0:54:02 server id 176200852 end_log_pos 7806 CRC32 0xff923caa Xid = 2645 COMMIT/*!*/; # at 7806 #190118 0:54:03 server id 176200852 end_log_pos 7871 CRC32 0x41f1db8c Anonymous_GTID last_committed=22 sequence_number=23 SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/; # at 7871 #190118 0:54:03 server id 176200852 end_log_pos 7946 CRC32 0x546cf104 Query thread_id=227 exec_time=0 error_code=0 SET TIMESTAMP=1547740443/*!*/; BEGIN /*!*/;
クエリの発見
- mysqlbinlogの出力では 1クエリは
# at (Number)から始まる - update文のpostion: 7685より前に戻せばok
- mysqlbinlogの出力では 1クエリは
binlogポジションまでのリカバリ
xtrabackupによるリカバリは省略
xtrabackup取得時のpositionの確認
- less /path/to/xtrabackup.log
MySQL binlog position: filename 'binary_log.000007', position '3002'念の為確認
mysqlbinlog --no-defaults --base64-output=DECODE-ROWS -vv --start-position 3002 --stop-position 7685 binary_log.000007 | lessstop-positionはそのidを含まない
mysqlbinlogは最後がbeginで終わっていると(おそらくトランザクションがcommitされていないと)勝手にrollbackを入れてくれる
# at 7610 #190118 0:54:02 server id 176200852 end_log_pos 7685 CRC32 0xc95b8674 Query thread_id=12 exec_time=0 error_code=0 SET TIMESTAMP=1547740442/*!*/; BEGIN /*!*/; ROLLBACK /* added by mysqlbinlog */ /*!*/; SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
# cd /mysql/logs # for i in $(ls binary_log.0*) do ext=$(echo $i | cut -d'.' -f2) cp $i relay_log.$ext done
- relay_log.indexの作成もする
# ls relay_log.0* > relay_log.index # cat relay_log.index relay_log.000001 relay_log.000002 relay_log.000003 relay_log.000004 relay_log.000005 relay_log.000006 relay_log.000007 # chown mysql. *relay*
起動してPITR実践
>select * from t1; +----+------+ | id | c1 | +----+------+ | 1 | 1 | | 2 | 2 | | 3 | 3 | | 4 | 4 | | 5 | 5 | | 6 | 6 | | 7 | 7 | +----+------+ 7 rows in set (0.01 sec) root@localhost:d1 01:09:29>SET GLOBAL server_id = 99; Query OK, 0 rows affected (0.00 sec) root@localhost:d1 01:10:00>set global slave_parallel_type='logical_clock'; Query OK, 0 rows affected (0.00 sec) root@localhost:d1 01:10:06>set global slave_parallel_workers=8; Query OK, 0 rows affected (0.00 sec) root@localhost:d1 01:10:11>CHANGE MASTER TO RELAY_LOG_FILE='relay_log.000007', RELAY_LOG_POS=3002, MASTER_HOST='dummy'; Query OK, 0 rows affected (0.00 sec) root@localhost:d1 01:10:54>show slave status\G *************************** 1. row *************************** Slave_IO_State: Master_Host: dummy Master_User: Master_Port: 3306 Connect_Retry: 60 Master_Log_File: Read_Master_Log_Pos: 4 Relay_Log_File: relay_log.000007 Relay_Log_Pos: 3002 Relay_Master_Log_File: Slave_IO_Running: No Slave_SQL_Running: No 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: 0 Relay_Log_Space: 30851 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: NULL 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: 0 Master_UUID: Master_Info_File: /mysql/data/master.info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: 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 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: 1 row in set (0.00 sec) root@localhost:d1 01:11:05>START SLAVE SQL_THREAD UNTIL RELAY_LOG_FILE = 'relay_log.000007', RELAY_LOG_POS = 7685; Query OK, 0 rows affected, 2 warnings (0.00 sec) Note (Code 1278): It is recommended to use --skip-slave-start when doing step-by-step replication with START SLAVE UNTIL; otherwise, you will get problems if you get an unexpected slave's mysqld restart Note (Code 1753): UNTIL condtion is not supported in multi-threaded slave mode. Slave is started in the sequential execution mode. root@localhost:d1 01:11:54>show slave status\G *************************** 1. row *************************** Slave_IO_State: Master_Host: dummy Master_User: Master_Port: 3306 Connect_Retry: 60 Master_Log_File: Read_Master_Log_Pos: 4 Relay_Log_File: relay_log.000007 Relay_Log_Pos: 7806 Relay_Master_Log_File: Slave_IO_Running: No Slave_SQL_Running: No 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: 7806 Relay_Log_Space: 30851 Until_Condition: Relay Until_Log_File: relay_log.000007 Until_Log_Pos: 7685 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: NULL 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: 0 Master_UUID: Master_Info_File: /mysql/data/master.info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: 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 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: 1 row in set (0.00 sec) root@localhost:d1 01:12:07>select * from t1; +----+------+ | id | c1 | +----+------+ | 1 | 0 | | 2 | 0 | | 3 | 0 | | 4 | 0 | | 5 | 0 | | 6 | 0 | | 7 | 0 | | 8 | 0 | | 9 | 0 | | 10 | 0 | | 11 | 0 | | 12 | 0 | | 13 | 0 | | 14 | 0 | | 15 | 0 | +----+------+ 15 rows in set (0.00 sec)
start slaveのuntilは指定されたポジションのトランザクションまでを実行するのかもしれない。 7684までに実行範囲を変えてみる
7684に変えてもだめだった。。。
start slave until...に関して
log_posの周辺を整理すると以下のような感じ
7684を指定してもupdateが走ってしまったことからbeginされたコミットを通ったものは実行されてしまう様子。 mysqlbinlogであれば時刻指定でbiginされただけのものがあれば自動でrollbackされるがreplicationのstop slave untilはそういったことがない。
beginを実行する前のクエリのポジション(7545)までを指定して実行したらうまく行った。
(うまく行った結果は書くの面倒なので省略)
ここまでのまとめ
- 貼り付けた実行結果の途中でもnoteが出ているように
Note (Code 1753): UNTIL condtion is not supported in multi-threaded slave mode. Slave is started in the sequential execution mode.なので、MTSとしてマルチスレッドでは適用できていない様子。(5.7だからか？) - untilによるポジション指定でbeginよりも後を指定した際にbeginされたトランザクションがabortされるか？に関してはドキュメントにないのでつらい。
- until句はioスレッドには効かないので、ioスレッドの方で止めることもできない。(効かないが、okは返ってくる(GTIDモードではioスレッドに対してもuntil句が有効)
