tom__bo’s Blog

えんじにゃ〜

RockstarらしいPITRの検証

where句なしでupdate文を実行するというオペミスがあった際にdummyのrelay_log(binlogをrenameしたもの)を使って、1ホスト単体でMTSを利用した一人replication的なことをしてPITRする方法の検証をしてみた。
何いってんだと思ったら下のlefredの発表資料を見てみてください。

その過程でいくつかの疑問が出てきたので、そこまでを書いていく。
↓の発言に至った経緯と思ってもらえると良いです。

MySQL 5.7.17, GTID=OFFでの検証。

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での実験をされている

fibonacci.hatenablog.jp

実験

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
  • 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 | less
        • stop-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*/;
  • binlogをrelay_logにしてmysql, sql_thread起動
    • binlogをrelay_logにrename
# 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句が有効)