レプリケーションのゆるーいお話その2 - 三流エンジニアの落書き帳

もう2019年も終わりですね。

僕は今年初めて冬コミに参加してみたのですが、やっぱり人が多いですね～

昼頃に行って正解でした。（夏は気温的に無理かな～）

さてさて、前回はMySQLのレプリケーションについてその概要を書きました。

今回は実際に手元でレプリケーションを構築してみたいと思います。

レプリケーションの仕組み
binary logのフォーマット
各フォーマットの中身
- STATEMENT
- ROW
まとめ

レプリケーションの仕組み

構築に入る前に少しレプリケーションの仕組みについて触れてみましょう。

前回レプリケーションの原理を「同じ箱に同じものを同じ順番で入れていけば最終的にどちらも同じ状態になる」と表現しました。この同じものを同じ順番でというのが一番重要でこの前提が崩れるともはや意味のないレプリケーションとなってしまいます。（意図的にこの前提を崩すレプリケーションフィルターというものがあるのですがそれはいったん置いておきましょう）

レプリケーションにおいて最も重要なものは何かと問われればbinary log（バイナリログ、以降はbinlogと表記）ではないかと僕は思います。 binlogはDBへの変更を記録したログであり、SlaveはMasterへbinlogを転送してもらい、その内容を自分にも適用させることでMasterと同じ状態にする（すなわち複製）ことを実現します。

すなわちbinlogが無いとレプリケーションは実現できないのです。

ここでレプリケーションの仕組みを順を追ってみてみましょう。

Slaveでレプリケーションを開始する(CHANGE MASTER文の実行)
MasterがSlaveにbinlog転送を行う(Binlog Dump)
IOスレッドがbinlogの内容をrelay logに書き込む
SQLスレッドがrelay logの内容を実行する

細かいところは端折りましたが、大体こんな感じでしょうか。簡単に用語の整理をしておきましょう。

IO Thread：Masterの更新内容をrelay logに書き込むスレッド、大抵SQLスレッドより高速

SQL Thread：relay logの内容を実際にDBに適用させるスレッド、大抵IOスレッドより低速

relay log：Slaveにのみ作られるMasterの更新内容を記録したもの、中身的にはbinlogとあまり変わらない

binary logのフォーマット

さて、binlogには3種類のフォーマットがあります。

STATEMENT
ROW
MIXED

これらのフォーマットはbinlog_formatというシステム変数によって制御されます。

binlog_format='STATEMENT'

このフォーマットではMasterで実行されたSQLをそのままbinlogに記録します。このフォーマットではbinlogのファイルサイズがROWフォーマットと比べて小さいなどのメリットがありますが、後述する非決定性のクエリが実行されるとMasterとSlaveの間でデーの不整合が発生してしまう恐れがあります。（さらに悪いことにSTATEMENTベースではそのデータの不整合に気づきづらいといったデメリットもあります）

binlog_format=STATEMENTで構成されるレプリケーションをSBR(Statement Base Replication)などと表現します。

昔のMySQL(5.6の初期頃だったかな？)のデフォルトではこれでした。

binlog_format='ROW'

このフォーマットではMasterで実際に変更された内容がbinlogに記録されます。このフォーマットではbinlogのファイルサイズがSTATEMENTフォーマットと比べて大きくなりやすいというデメリットがありますが、非決定性のクエリが実行されてもMasterとSlaveの間でデータの不整合は発生しません。

最近のMySQLではこれが標準になっていますし、ROWフォーマットでないと利用できない機能も多々あります。

binlog_format=ROWで構成されるレプリケーションをRBR(Row Base Replication)などと表現します。

binlog_format='MIXED'

名前からもわかると思いますが、このフォーマットでは基本的にSTATEMENTベースで書き込まれ非決定性のクエリが実行された際にROWベースで書き込まれます。一見すると上2つのフォーマットの良いところ取りなのですが、意図せずROWベースで書き込まれている場合もあるので要注意です。

非決定性のクエリ

クエリや関数にはどのように実行しても結果が変わらない決定性のものと実行する度に結果が変わってしまう非決定性のものがあります。非決定性のものは例えば下記のようなものです。

ORDER BYを伴わないLIMIT
UUID()

このようなクエリ、関数を積極的に使用する場合はROWベースレプリケーションを使うべきでしょう。

各フォーマットの中身

さて、各フォーマットについて概要をざっくりまとめましたが、今度は実際にその中身を見てみましょう。

mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.18    |
+-----------+
1 row in set (0.00 sec)

mysql> select * from t1;
+---+------+------+
| a | b    | c    |
+---+------+------+
| 1 | a    |  200 |
| 2 | b    |  200 |
| 3 | c    |  200 |
| 4 | d    |  200 |
| 5 | e    |  200 |
+---+------+------+
5 rows in set (0.00 sec)

こんなテーブルに対して次のようなクエリを実行してみてbinlogフォーマットの違いでどのような変化が現れるでしょう。

UPDATE t1 SET c = c + 100;

なお、binlogの中身はその名の通りバイナリ形式で書かれておりそのままでは人間が読める形になっていません。そこで使うツールがmysqlbinlogです。mysqlbinlogはバイナリで書かれているbinlogを人間が読める形に変換してくれます。

STATEMENT

koreshiki@LAPTOP-CONIPJL6:~/mysql-sandboxes/5000/sandboxdata$ mysqlbinlog LAPTOP-CONIPJL6-bin.000012
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#191231 22:42:40 server id 662490994  end_log_pos 124   Start: binlog v 4, server v 8.0.18 created 191231 22:42:40
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
UFALXg9yz3wneAAAAHwAAAABAAQAOC4wLjE4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgA+7qzM
'/*!*/;
# at 124
#191231 22:42:40 server id 662490994  end_log_pos 191   Previous-GTIDs
# 274941c5-2a54-11ea-be32-94b86d82d803:1-277
# at 191
#191231 22:42:46 server id 662490994  end_log_pos 266   GTID    last_committed=0        sequence_number=1       rbr_only=no     original_committed_timestamp=1577799766986996        immediate_commit_timestamp=1577799766986996     transaction_length=292
# original_commit_timestamp=1577799766986996 (2019-12-31 22:42:46.986996 JST)
# immediate_commit_timestamp=1577799766986996 (2019-12-31 22:42:46.986996 JST)
/*!80001 SET @@session.original_commit_timestamp=1577799766986996*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= '274941c5-2a54-11ea-be32-94b86d82d803:278'/*!*/;
# at 266
#191231 22:42:46 server id 662490994  end_log_pos 351   Query   thread_id=44    exec_time=0     error_code=0
SET TIMESTAMP=1577799766/*!*/;
SET @@session.pseudo_thread_id=44/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 351
#191231 22:42:46 server id 662490994  end_log_pos 456   Query   thread_id=44    exec_time=0     error_code=0
use `dba`/*!*/;
SET TIMESTAMP=1577799766/*!*/;
update t1 set c = c + 100
/*!*/;
# at 456
#191231 22:42:46 server id 662490994  end_log_pos 483   Xid = 1700
COMMIT/*!*/;
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*/;

注目していただきたいのは下記の部分です。

# at 351
#191231 22:42:46 server id 662490994  end_log_pos 456   Query   thread_id=44    exec_time=0     error_code=0
use `dba`/*!*/;
SET TIMESTAMP=1577799766/*!*/;
update t1 set c = c + 100
/*!*/;

STATEMENTベースではMasterで実行したクエリがそのままbinlogに書き込まれていることがわかりますね。

ROW

koreshiki@LAPTOP-CONIPJL6:~/mysql-sandboxes/5000/sandboxdata$ mysqlbinlog LAPTOP-CONIPJL6-bin.000014
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#191231 22:44:08 server id 662490994  end_log_pos 124   Start: binlog v 4, server v 8.0.18 created 191231 22:44:08
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
qFALXg9yz3wneAAAAHwAAAABAAQAOC4wLjE4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgD+pM9A
'/*!*/;
# at 124
#191231 22:44:08 server id 662490994  end_log_pos 191   Previous-GTIDs
# 274941c5-2a54-11ea-be32-94b86d82d803:1-279
# at 191
#191231 22:44:14 server id 662490994  end_log_pos 266   GTID    last_committed=0        sequence_number=1       rbr_only=yes    original_committed_timestamp=1577799854509398        immediate_commit_timestamp=1577799854509398     transaction_length=373
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1577799854509398 (2019-12-31 22:44:14.509398 JST)
# immediate_commit_timestamp=1577799854509398 (2019-12-31 22:44:14.509398 JST)
/*!80001 SET @@session.original_commit_timestamp=1577799854509398*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= '274941c5-2a54-11ea-be32-94b86d82d803:280'/*!*/;
# at 266
#191231 22:44:14 server id 662490994  end_log_pos 345   Query   thread_id=44    exec_time=0     error_code=0
SET TIMESTAMP=1577799854/*!*/;
SET @@session.pseudo_thread_id=44/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 345
#191231 22:44:14 server id 662490994  end_log_pos 397   Table_map: `dba`.`t1` mapped to number 365
# at 397
#191231 22:44:14 server id 662490994  end_log_pos 537   Update_rows_v1: table id 365 flags: STMT_END_F

BINLOG '
rlALXhNyz3wnNAAAAI0BAAAAAG0BAAAAAAEAA2RiYQACdDEAAwMPAwJQAAYBAQACA/z/AA==
rlALXhhyz3wnjAAAABkCAAAAAG0BAAAAAAEAA///AAEAAAABYWQAAAAAAQAAAAFhyAAAAAACAAAA
AWJkAAAAAAIAAAABYsgAAAAAAwAAAAFjZAAAAAADAAAAAWPIAAAAAAQAAAABZGQAAAAABAAAAAFk
yAAAAAAFAAAAAWVkAAAAAAUAAAABZcgAAAA=
'/*!*/;
# at 537
#191231 22:44:14 server id 662490994  end_log_pos 564   Xid = 1705
COMMIT/*!*/;
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フォーマットがROWだとそのままmysqlbinlogで変換しても人間が読める形になりません。

そこでmysqlbinlogに-vv, --base64-output=DECODE-ROWSオプションを付与して実行しなくてはいけません。

koreshiki@LAPTOP-CONIPJL6:~/mysql-sandboxes/5000/sandboxdata$ mysqlbinlog -vv --base64-output=DECODE-ROWS LAPTOP-CONIPJL6-bin.000015
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#191231 22:49:16 server id 662490994  end_log_pos 124   Start: binlog v 4, server v 8.0.18 created 191231 22:49:16
# Warning: this binlog is either in use or was not closed properly.
# at 124
#191231 22:49:16 server id 662490994  end_log_pos 191   Previous-GTIDs
# 274941c5-2a54-11ea-be32-94b86d82d803:1-281
# at 191
#191231 22:49:22 server id 662490994  end_log_pos 266   GTID    last_committed=0        sequence_number=1       rbr_only=yes    original_committed_timestamp=1577800162588985        immediate_commit_timestamp=1577800162588985     transaction_length=418
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1577800162588985 (2019-12-31 22:49:22.588985 JST)
# immediate_commit_timestamp=1577800162588985 (2019-12-31 22:49:22.588985 JST)
/*!80001 SET @@session.original_commit_timestamp=1577800162588985*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= '274941c5-2a54-11ea-be32-94b86d82d803:282'/*!*/;
# at 266
#191231 22:49:22 server id 662490994  end_log_pos 345   Query   thread_id=44    exec_time=0     error_code=0
SET TIMESTAMP=1577800162/*!*/;
SET @@session.pseudo_thread_id=44/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 345
#191231 22:49:22 server id 662490994  end_log_pos 390   Rows_query
# update t1 set c = c + 100
# at 390
#191231 22:49:22 server id 662490994  end_log_pos 442   Table_map: `dba`.`t1` mapped to number 365
# at 442
#191231 22:49:22 server id 662490994  end_log_pos 582   Update_rows_v1: table id 365 flags: STMT_END_F
### UPDATE `dba`.`t1`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='a' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='a' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='b' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='b' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=4 /* INT meta=0 nullable=0 is_null=0 */
###   @2='d' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=4 /* INT meta=0 nullable=0 is_null=0 */
###   @2='d' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=5 /* INT meta=0 nullable=0 is_null=0 */
###   @2='e' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=5 /* INT meta=0 nullable=0 is_null=0 */
###   @2='e' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
# at 582
#191231 22:49:22 server id 662490994  end_log_pos 609   Xid = 1714
COMMIT/*!*/;
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*/;

注目していただきたいところは

# at 442
#191231 22:49:22 server id 662490994  end_log_pos 582   Update_rows_v1: table id 365 flags: STMT_END_F
### UPDATE `dba`.`t1`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='a' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='a' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='b' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='b' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=4 /* INT meta=0 nullable=0 is_null=0 */
###   @2='d' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=4 /* INT meta=0 nullable=0 is_null=0 */
###   @2='d' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */
### UPDATE `dba`.`t1`
### WHERE
###   @1=5 /* INT meta=0 nullable=0 is_null=0 */
###   @2='e' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=100 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=5 /* INT meta=0 nullable=0 is_null=0 */
###   @2='e' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
###   @3=200 /* INT meta=0 nullable=1 is_null=0 */

各カラムが@1のように表現されています。このテーブルでは@1=a, @2=b, @3=cです。

このように実際に変更のあった行をbinlogに記録されます。またこのようなフォーマットのため行ベースレプリケーション環境だとSlave側でテーブルに対してPrimary key(主キー)がテーブルスキャンが発生してしまいますので注意が必要です。

また、上の例からもわかるように簡単な更新クエリだったとしても対象の行が多いとbinlogに大量にその変更が書き込まれるのでそういった点もしっかり頭に入れておくべきでしょう。(100万行に対してUPDATEすると・・・)

ちなみに実際に実行されたオリジナルのクエリを確認するためにはbinlog_rows_query_log_eventsシステム変数をONしておく必要がありますが、この変数を有効にしている場合オリジナルクエリはRows_queryと表示されているすぐ下に表示されます。

koreshiki@LAPTOP-CONIPJL6:~/mysql-sandboxes/5000/sandboxdata$ mysqlbinlog -vv --base64-output=DECODE-ROWS LAPTOP-CONIPJL6-bin.000015 | grep -A1 Rows_query
#191231 22:49:22 server id 662490994  end_log_pos 390   Rows_query
# update t1 set c = c + 100

と、ここまで書いて思った以上に長くなってしまったので実際にレプリケーションを構築するのは次回以降に持ち越しましょう。

まとめ

そんなわけで今回は各binlogフォーマットの特徴とそれらの中身を実際に確認してみました。

今年ももう少しでおしまいです。僕はこれからガキ使見ながら年越しします。