Binary Log Transaction Compressionについて調べてみる
MySQL8.0.20からバイナリログの圧縮が可能になりました。 リファレンスにはBinary Log Transaction Compression(ここでは便宜上バイナリログトランザクション圧縮と訳します)という名目になっています。
ということで
MySQL :: MySQL 8.0 Reference Manual :: 5.4.4.5 Binary Log Transaction Compression
を見ながら自分用にメモを書いていこうと思います。
また、最後に実際にバイナリログの圧縮を有効にする場合、どの程度パフォーマンスに影響を与えるのかも試したいと思います！
3行で
MySQL8.0.20からBinary Log Transaction Compressionと呼ばれるバイナリログの圧縮機能が追加された
圧縮はzstdによって行われ、圧縮レベルもzstd同様1-22で選択できる
圧縮機能を使うとストレージ、ネットワーク帯域幅を節約できるが、その分CPU、メモリを消費する
概要
この機能を有効にするとトランザクションペイロードがzstdアルゴリズムによって圧縮されます。 圧縮は1トランザクションごとに行われます。 そして圧縮された内容がバイナリログにシングルイベント（これはTransaction payroad eventと表現されます）として書き込まれます。
圧縮されたトランザクションペイロードは圧縮されたままレプリケートされるためリレーログも圧縮されることになります。 バイナリログ、リレーログともに圧縮されることになるのでMaster,SlaveないしはPrimary,Secondaryのストレージの節約につながります。
圧縮されたトランザクションペイロードはSlaveなどがMasterからの更新を受け取り、その内容を自身にも適用させるときに解凍されます。
そのほかにもmysqlbinlogやSHOW BINLOG EVENTSの実行時にも解凍されるようです。
Binary Log Transaction Compressionの有効化
バイナリログトランザクション圧縮を有効にするためにはbinlog_transaction_compressionをONにします。
また圧縮レベルを制御するbinlog_transaction_compression_level_zstdという変数もあります。
この変数はzstdと同じく1(最低)から22(最高)まで指定することが可能です。デフォルトは3となっています。
圧縮レベルを上げるとその分ストレージを節約できますが、多くのCPUとメモリを使うため注意したほうがよさそうです。
もっと言うと例えば圧縮レベルを3から6と2倍にしても圧縮率は2倍になりません。
これらの変数はSET GLOBALで変更可能ですが、既存のセッションは再度接続する必要があります。
なお、バイナリログトランザクション圧縮を有効にしてもバイナリログの暗号化は使用できるようです。
Binary Log Transaction Compressionを有効にしても圧縮されないイベント
バイナリログトランザクション圧縮を有効にしても圧縮されないケースがいくつかあります。
- (Anonymous GTID eventを含む)GTID関連のイベント
例えばバイナリログに含まれるSET @@SESSION.GTID_NEXT= 'ANONYMOUS'などがこれに該当するのかなと思われます。
- ビューの変更、ハートビートのような制御イベント
（このあたりはGroup Replicationとかが大きく関係してくるのかな？）
例えばMyISAMなどトランザクションをサポートしないテーブルへの更新・変更、
CREATE TABLEなどDDLもトランザクショナルではないのでこれに当てはまります。
- STATEMENTベースで記録されるトランザクションイベント
バイナリログトランザクション圧縮が有効になるのは、ROWベースのトランザクションイベントのみだそうです。
まあ今さらSTATEMENTベースで動いているレプリケーション環境なんてありませんよね・・・？
Binary Log Transaction Compression有効時の挙動
サポート
バイナリログトランザクション圧縮を有効にしても圧縮されたトランザクションは他のトランザクションと同じように ロールバック、レプリケーションフィルター、XAトランザクションをサポートします。
パケット
max_allowed_packetおよびslave_max_allowed_packetは圧縮されたTransaction payroad eventに対して適用されます。
つまりバイナリログの圧縮はネットワーク帯域幅の節約にもつながるということですね。
マルチスレッドスレーブ(MTS)
マルチスレッドスレーブ環境では、各Transaction payroad eventはワーカースレッドに割り当てられます。 各ワーカースレッドはそのペイロードを解凍し個々のトランザクションを順に適用させます。 もし適用させようとしたペイロードにエラーが含まれればワーカースレッドはコーディネーターにその旨を報告します。
slave_parallel_typeがDATABASEの場合、トランザクションの影響を受けるデータベースはすべて、トランザクションがスケジューリングされる前にマップされます。
その影響で、この環境では圧縮を利用しない環境と比べて並行性が下がる可能性があります。
（slave_parallel_type = DATABASEを進んで使う環境はあまりなさそうな気がするのでそこまで気にする必要はなさそう？）
Semi-Sync Replication
準同期レプリケーション環境では、完全なTransaction payroad eventが受信できた後、Masterに応答を返します。
チェックサム
binlog_checksumが有効である場合、圧縮されたトランザクションペイロードの個々のイベントについてチェックサムを書き込みません。
その代わり完全なTransaction payroad eventに対してチェックサムを書き込みます。
圧縮されないイベントに対しては従来と同じくイベントごとにチェックサムを書き込みます。
その他
sql_slave_skip_counterを使ってイベントをスキップする場合Transaction payroad eventは1つのイベントとして計算されます。
すなわちTransaction payroad eventに含まれる個々のイベントが丸ごとスキップされることを意味します。
Transaction payroad eventは1つのトランザクションごとに作られるので納得ですね。
そもそも、GTIDベースレプリケーションを使っていればsql_slave_skip_counterを使うことはありませんし、 GTID＋ROWベース+ロスレプリケーションを使っていればMasterとSlaveで不整合が発生することはほとんど無いかと思います。
圧縮と非圧縮の組み合わせ
バイナリログトランザクション圧縮をサポートするMySQLリリースでは、バイナリログトランザクション圧縮および非圧縮の混合をサポートします。
Master/SlaveやGroup Replicationで各サーバ個別でバイナリログトランザクションを圧縮するか非圧縮するかを決めることができます。統一する必要はありません
バイナリログトランザクション圧縮を有効にしてから無効にしても、圧縮されたものは引き続き圧縮された状態で処理がされます
SET SESSIONでbinlog_transaction_compressionをセッションごとに変更すると圧縮されたものと圧縮されないペイロードが混合します
Replicationの挙動
- MasterとSlaveがともにバイナリログトランザクション圧縮を有効にしている場合
Masterで圧縮されたペイロードはそのままSlaveに転送されリレーログに圧縮されたまま書き込まれます。 それを解凍してからトランザクションを適用させ、Slave自身のバイナリログに書き込むときに再度圧縮されます。
- Masterのみバイナリログトランザクション圧縮を有効にしている場合
Slaveは圧縮されたペイロードを受け取って、圧縮した状態でリレーログに書き込みます。 トランザクションを適用させるときにそれらを解凍し、バイナリログを有効にしていれば圧縮せずに自身のバイナリログに書き込みます。
- Slaveのみバイナリログトランザクション圧縮を有効にしている場合
もしSlaveでバイナリログが有効になっていれば、トランザクションを適用させた後、圧縮させてバイナリログに書き込みます。
結構重要そうな制限
SlaveがMySQL8.0.20より前のリリースの場合、バイナリログトランザクション圧縮を有効にしているMasterからレプリケーションできません。
MasterがMySQL8.0.20より前のリリースの場合、Slaveはバイナリログトランザクション圧縮を有効にしてもレプリケーションでき、 なおかつ自身のバイナリログに書き込むときは圧縮することができます。
モニタリング
MySQL8.0.20からperformance_schemaにbinary_log_transaction_compression_statsという新しいテーブルが追加されました。
mysql80-root@localhost:[(none)] >DESC performance_schema.binary_log_transaction_compression_stats; +--------------------------------------+------------------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +--------------------------------------+------------------------+------+-----+---------+-------+ | LOG_TYPE | enum('BINARY','RELAY') | NO | | NULL | | | COMPRESSION_TYPE | varchar(64) | NO | | NULL | | | TRANSACTION_COUNTER | bigint unsigned | NO | | NULL | | | COMPRESSED_BYTES_COUNTER | bigint unsigned | NO | | NULL | | | UNCOMPRESSED_BYTES_COUNTER | bigint unsigned | NO | | NULL | | | COMPRESSION_PERCENTAGE | smallint | NO | | NULL | | | FIRST_TRANSACTION_ID | text | YES | | NULL | | | FIRST_TRANSACTION_COMPRESSED_BYTES | bigint unsigned | NO | | NULL | | | FIRST_TRANSACTION_UNCOMPRESSED_BYTES | bigint unsigned | NO | | NULL | | | FIRST_TRANSACTION_TIMESTAMP | timestamp(6) | YES | | NULL | | | LAST_TRANSACTION_ID | text | YES | | NULL | | | LAST_TRANSACTION_COMPRESSED_BYTES | bigint unsigned | NO | | NULL | | | LAST_TRANSACTION_UNCOMPRESSED_BYTES | bigint unsigned | NO | | NULL | | | LAST_TRANSACTION_TIMESTAMP | timestamp(6) | YES | | NULL | | +--------------------------------------+------------------------+------+-----+---------+-------+ 14 rows in set (0.01 sec)
このテーブルから監視期間のバイナリログの圧縮率や最後のトランザクションに対する圧縮の影響（どの程度圧縮されたのかなど）を監視できます。
このテーブルをTRUNCATE TABLEすることによって監視をリセットすることができます。
LOG_TYPEというカラムから分かるようにバイナリログとリレーログはしっかり区別されるようです。
ただし、バイナリログから統計を取るのかバイナリログが無いと統計データが生成できないようです。
mysqlbinlogとBinary Log Transaction Compression
--verboseオプション(短縮形は-v)をつけると圧縮されたペイロードのサイズ、非圧縮のままのペイロードのサイズおよび使用された圧縮アルゴリズムがコメントとして表示されます。
例えば下記のようになります。
# at 233 #200506 0:58:27 server id 1 end_log_pos 402 CRC32 0x2e0efc3c Transaction_Payload payload_size=136 compression_type=ZSTD uncompressed_size=186 # Start of compressed events! # at 402 #200506 0:58:19 server id 1 end_log_pos 402 CRC32 0x99d8b64f Query thread_id=4100 exec_time=0 error_code=0 SET TIMESTAMP=1588694299/*!*/; SET @@session.pseudo_thread_id=4100/*!*/; 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 402 #200506 0:58:19 server id 1 end_log_pos 402 CRC32 0x5c3b2e4a Table_map: `db1`.`t1` mapped to number 115 # at 402 #200506 0:58:19 server id 1 end_log_pos 402 CRC32 0xd114ef8f Write_rows: table id 115 flags: STMT_END_F BINLOG ' G42xXhMBAAAAMQAAAAAAAAAAAHMAAAAAAAEAA2RiMQACdDEAAwMDAwAGAQGASi47XA== G42xXh4BAAAAMAAAAAAAAAAAAHMAAAAAAAEAAgAD/wAgAAAAIQAAACEAAACP7xTR '/*!*/; ### INSERT INTO `db1`.`t1` ### SET ### @1=32 ### @2=33 ### @3=33 # at 402 #200506 0:58:27 server id 1 end_log_pos 402 CRC32 0xa60b8c39 Xid = 4012438 COMMIT/*!*/; # End of compressed events! 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*/;
Start of compressed events!が圧縮の開始、End of compressed events!が圧縮の終了を表します。
このコメントに囲まれる部分が圧縮されていることになります。
2行目に圧縮に関するコメントが表示されています。
payload_sizeが圧縮されたペイロードのサイズ、compression_typeが使用された圧縮アルゴリズム、uncompressed_sizeが圧縮されないまま残った分のサイズですね。 将来compression_typeにはZSTD以外も追加されるのでしょうかね。
Group Replicationと圧縮
Group Replicationではgroup_replication_compression_thresholdを超えるメッセージはデフォルトで圧縮されます。
また分散リカバリ時の圧縮を制御するgroup_replication_recovery_compression_algorithms,
group_replication_recovery_zstd_compression_levelなどもあります。
これらGroup Replication独自の圧縮に加えてバイナリログトランザクション圧縮を有効にできます。
検証
簡単にパフォーマンステストを行ってみます。
検証環境
ホストOS : Windows10
ゲストOS : CentOS 8.1.1911 (Oracle Virtualbox)
パラメータ
server memory 4G innodb_buffer_pool_size = 2G innodb_buffer_pool_instance = 8 innodb_flush_method = O_DIRECT sync_binlog = 1 binlog_group_commit_sync_delay = 0 binlog_group_commit_sync_no_delay_count = 0 max_binlog_size = 128M thread_cache_size = 128 max_connections = 300 autocommit=ON
バイナリログトランザクション圧縮による影響(圧縮率とパフォーマンス)を見たいので、限られた時間にどの程度トランザクションを実行できたかを計測するのではなく、限られた仕事をどの程度の時間でできたかを見てみます。
update.sh
#!/bin/bash request=5000 max_range=1100000 # = select count(*) from sbtest1; for i in `seq 1 $request`;do n=$(echo $RANDOM) target=$(echo $((RANDOM % max_range))) stmt="UPDATE sbtest1 SET k = $n WHERE id = $target;" mysql -D sbtest -e "$stmt" done
メモリに乗り切るサイズの単一テーブルに対してUPDATEをかけていくスクリプトです。
単純に5000回シングルスレッドでUPDATEするのにどの程度時間がかかるのか、 バイナリログのサイズがどの程度圧縮されるのか見ていきます。
圧縮無し
[root@centos8-instance3:/home/scripts/bin]# mysql -e "show global variables like 'binlog%compression%'; show binary logs;"; +-------------------------------------------+-------+ | Variable_name | Value | +-------------------------------------------+-------+ | binlog_transaction_compression | OFF | | binlog_transaction_compression_level_zstd | 3 | +-------------------------------------------+-------+ +---------------+-----------+-----------+ | Log_name | File_size | Encrypted | +---------------+-----------+-----------+ | binlog.000001 | 106623059 | No | | binlog.000002 | 160255513 | No | | binlog.000003 | 81846423 | No | | binlog.000004 | 176064573 | No | | binlog.000005 | 140793 | No | | binlog.000006 | 196 | No | +---------------+-----------+-----------+ [root@centos8-instance3:/home/scripts/bin]# time ./update.sh real 1m8.681s user 0m29.180s sys 0m13.772s [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs;"; +---------------+-----------+-----------+ | Log_name | File_size | Encrypted | +---------------+-----------+-----------+ | binlog.000001 | 106623059 | No | | binlog.000002 | 160255513 | No | | binlog.000003 | 81846423 | No | | binlog.000004 | 176064573 | No | | binlog.000005 | 140793 | No | | binlog.000006 | 3395196 | No | +---------------+-----------+-----------+
次にバイナリログトランザクション圧縮を有効にしてみます。
とりあえず圧縮レベルはデフォルトの3にしておきます。
圧縮あり 圧縮レベル=3
[root@centos8-instance3:/home/scripts/bin]# mysql -e "show global variables like 'binlog%compression%'; show binary logs;"; +-------------------------------------------+-------+ | Variable_name | Value | +-------------------------------------------+-------+ | binlog_transaction_compression | ON | | binlog_transaction_compression_level_zstd | 3 | +-------------------------------------------+-------+ +---------------+-----------+-----------+ | Log_name | File_size | Encrypted | +---------------+-----------+-----------+ | binlog.000001 | 106623059 | No | | binlog.000002 | 160255513 | No | | binlog.000003 | 81846423 | No | | binlog.000004 | 176064573 | No | | binlog.000005 | 140793 | No | | binlog.000006 | 3395240 | No | | binlog.000007 | 196 | No | +---------------+-----------+-----------+ [root@centos8-instance3:/home/scripts/bin]# time ./update.sh real 1m9.139s user 0m29.817s sys 0m12.604s [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs;"; +---------------+-----------+-----------+ | Log_name | File_size | Encrypted | +---------------+-----------+-----------+ | binlog.000001 | 106623059 | No | | binlog.000002 | 160255513 | No | | binlog.000003 | 81846423 | No | | binlog.000004 | 176064573 | No | | binlog.000005 | 140793 | No | | binlog.000006 | 3395240 | No | | binlog.000007 | 2097220 | No | +---------------+-----------+-----------+
実行時間の差はほとんど誤差レベルですね。 これはおそらく各トランザクションが極めて小さいため、圧縮にかかる時間がほとんどかかっていないからだと思われます。
一方でバイナリログのサイズは圧縮すると、圧縮しない時と比べて約60%ほどのサイズとなっています。
次にもう少し1つのトランザクションを大きくしてみようと思います。
ex_update.sh
#!/bin/bash request=5000 max_size=1100000 range=1000 for i in `seq 1 $request`;do n=$(echo $RANDOM) min_range=$(echo $((RANDOM % (range - target_range)))) max_range=$((min_range + range)) stmt="UPDATE sbtest1 SET k = $n WHERE id BETWEEN $min_range AND $max_range;" mysql -D sbtest -e "$stmt" done
1回のトランザクションで1000行にUPDATEするように変更します。
まあ単にBETWEENにしただけですが・・・
圧縮無し
[root@centos8-instance3:/home/scripts/bin]# mysql -e "show global variables like 'binlog%compression%'; show binary logs;"; +-------------------------------------------+-------+ | Variable_name | Value | +-------------------------------------------+-------+ | binlog_transaction_compression | OFF | | binlog_transaction_compression_level_zstd | 3 | +-------------------------------------------+-------+ +---------------+-----------+-----------+ | Log_name | File_size | Encrypted | +---------------+-----------+-----------+ | binlog.000001 | 106623059 | No | | binlog.000002 | 160255513 | No | | binlog.000003 | 81846423 | No | | binlog.000004 | 176064573 | No | | binlog.000005 | 140793 | No | | binlog.000006 | 3395240 | No | | binlog.000007 | 2097264 | No | | binlog.000008 | 108046 | No | | binlog.000009 | 196 | No | +---------------+-----------+-----------+ [root@centos8-instance3:/home/scripts/bin]# time ./ex_update.sh real 3m56.179s user 0m29.426s sys 0m14.214s [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs" | tail -1; binlog.000010 837756656 No
圧縮あり 圧縮レベル=3
[root@centos8-instance3:/home/scripts/bin]# mysql -e "set global binlog_transaction_compression = ON; flush binary logs" [root@centos8-instance3:/home/scripts/bin]# [root@centos8-instance3:/home/scripts/bin]# mysql -e "show global variables like 'binlog%compression%'"; +-------------------------------------------+-------+ | Variable_name | Value | +-------------------------------------------+-------+ | binlog_transaction_compression | ON | | binlog_transaction_compression_level_zstd | 3 | +-------------------------------------------+-------+ [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs" | tail -1 binlog.000011 196 No [root@centos8-instance3:/home/scripts/bin]# time ./ex_update.sh real 4m38.819s user 0m33.397s sys 0m16.726s [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs" | tail -1 binlog.000011 514905196 No
実行時間は約1.28倍、バイナリサイズは同様60%ほどですね。
トランザクションサイズが大きいと圧縮にかかる時間が無視できなくなるということが分かります。
試しに圧縮レベルを最大レベルにして再度試してみます。
圧縮あり 圧縮レベル=22(最大)
[root@centos8-instance3:/home/scripts/bin]# mysql -e "set global binlog_transaction_compression_level_zstd = 22; flush binary logs" [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs" | tail -1 binlog.000013 196 No [root@centos8-instance3:/home/scripts/bin]# mysql -e "show global variables like 'binlog%compression%'"; +-------------------------------------------+-------+ | Variable_name | Value | +-------------------------------------------+-------+ | binlog_transaction_compression | ON | | binlog_transaction_compression_level_zstd | 22 | +-------------------------------------------+-------+ [root@centos8-instance3:/home/scripts/bin]# time ./ex_update.sh real 4m19.021s user 0m31.063s sys 0m15.309s [root@centos8-instance3:/home/scripts/bin]# mysql -e "show binary logs" | tail -1 binlog.000013 514890551 No
なぜか、実行時間も速くなりました。
ただ圧縮具合がそこまで変わらないので何とも判断に迷いますね。
これだけ見ると圧縮度が劇的に変わらないのでとりあえずはデフォルトレベルでもいいのかなと思います。
バックアップ専用Slave(ロールチェンジにも使われない)とかであれば、 トランザクションの大きさとかを考慮しながら圧縮レベルを上げてみてもいいかもしれません。
おまけ
制約であるSlaveがMySQL8.0.20より前のリリースの場合、バイナリログトランザクション圧縮を有効にしているMasterからレプリケーションできないのか実際に試してみます。
Master
donor >SELECT version(); +-----------+ | version() | +-----------+ | 8.0.20 | +-----------+ 1 row in set (0.00 sec) -- まずは圧縮を無効にしておく mysql80-root@localhost:[performance_schema] >show global variables like '%binlog%compression%'; +-------------------------------------------+-------+ | Variable_name | Value | +-------------------------------------------+-------+ | binlog_transaction_compression | OFF | | binlog_transaction_compression_level_zstd | 3 | +-------------------------------------------+-------+ 2 rows in set (0.00 sec) donor >SHOW MASTER STATUS; +---------------+----------+--------------+------------------+-----------------------------------------------+ | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set | +---------------+----------+--------------+------------------+-----------------------------------------------+ | binlog.000011 | 66983854 | | | f6145d93-89f9-11ea-bb4c-0800271d8d54:1-432204 | +---------------+----------+--------------+------------------+-----------------------------------------------+ 1 row in set (0.00 sec) -- ここからSlave側 recipient >SELECT version(); +--------------+ | version() | +--------------+ | 8.0.19-debug | +--------------+ 1 row in set (0.00 sec) recipient >SET GLOBAL gtid_purged = 'f6145d93-89f9-11ea-bb4c-0800271d8d54:1-432204'; Query OK, 0 rows affected (0.04 sec) recipient >CHANGE MASTER TO -> MASTER_HOST='192.168.0.12', -> MASTER_PORT=3306, -> MASTER_USER='repl', -> MASTER_PASSWORD='repl', -> MASTER_AUTO_POSITION=1; Query OK, 0 rows affected, 2 warnings (0.06 sec) recipient >START SLAVE; Query OK, 0 rows affected (0.03 sec) recipient >SHOW SLAVE STATUS\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 192.168.0.12 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: binlog.000011 Read_Master_Log_Pos: 66983854 Relay_Log_File: centos8-mysql-relay-bin.000002 Relay_Log_Pos: 408 Relay_Master_Log_File: binlog.000011 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: 66983854 Relay_Log_Space: 624 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: 1 Master_UUID: f6145d93-89f9-11ea-bb4c-0800271d8d54 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 more updates 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: f6145d93-89f9-11ea-bb4c-0800271d8d54:1-432204 Auto_Position: 1 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: Master_public_key_path: Get_master_public_key: 0 Network_Namespace: 1 row in set (0.00 sec) -- ここからMaster側 donor >CREATE DATABASE repl_test; Query OK, 1 row affected (0.02 sec) donor >USE repl_test; Database changed donor > donor >CREATE TABLE t1(a int primary key); Query OK, 0 rows affected (0.13 sec) donor >INSERT INTO t1 VALUES (1); Query OK, 1 row affected (0.01 sec) -- ここからSlave recipient >USE repl_test; Database changed recipient >TABLE t1; +---+ | a | +---+ | 1 | +---+ 1 row in set (0.00 sec)
次にbinlog_transaction_compressionを有効にした状態でレプリケーションを試してみます。
donor >SET GLOBAL binlog_transaction_compression = 1; Query OK, 0 rows affected (0.00 sec) -- Slave再接続 recipient >STOP SLAVE; START SLAVE; Query OK, 0 rows affected (0.02 sec) Query OK, 0 rows affected (0.02 sec) recipient >SHOW SLAVE STATUS\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 192.168.0.12 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: binlog.000011 Read_Master_Log_Pos: 66984546 Relay_Log_File: centos8-mysql-relay-bin.000004 Relay_Log_Pos: 448 Relay_Master_Log_File: binlog.000011 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: 66984546 Relay_Log_Space: 957 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: 1 Master_UUID: f6145d93-89f9-11ea-bb4c-0800271d8d54 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 more updates Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: f6145d93-89f9-11ea-bb4c-0800271d8d54:432205-432207 Executed_Gtid_Set: f6145d93-89f9-11ea-bb4c-0800271d8d54:1-432207, f9af6ecc-8914-11ea-8b92-08002751a9d1:1 Auto_Position: 1 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: Master_public_key_path: Get_master_public_key: 0 Network_Namespace: 1 row in set (0.00 sec) -- Master側で更新 donor >INSERT INTO t1 VALUES (2); Query OK, 1 row affected (0.02 sec) donor >TABLE t1; +---+ | a | +---+ | 1 | | 2 | +---+ 2 rows in set (0.00 sec) -- Slave recipient >TABLE t1; +---+ | a | +---+ | 1 | +---+ 1 row in set (0.01 sec) recipient >SHOW SLAVE STATUS\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 192.168.0.12 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: binlog.000011 Read_Master_Log_Pos: 66984792 Relay_Log_File: centos8-mysql-relay-bin.000004 Relay_Log_Pos: 448 Relay_Master_Log_File: binlog.000011 Slave_IO_Running: Yes 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: 13121 Last_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, the server was unable to fetch a keyring key required to open an encrypted relay log file, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave. Skip_Counter: 0 Exec_Master_Log_Pos: 66984546 Relay_Log_Space: 1203 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: 13121 Last_SQL_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, the server was unable to fetch a keyring key required to open an encrypted relay log file, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave. Replicate_Ignore_Server_Ids: Master_Server_Id: 1 Master_UUID: f6145d93-89f9-11ea-bb4c-0800271d8d54 Master_Info_File: mysql.slave_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: 200506 23:59:32 Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: f6145d93-89f9-11ea-bb4c-0800271d8d54:432205-432207 Executed_Gtid_Set: f6145d93-89f9-11ea-bb4c-0800271d8d54:1-432207, f9af6ecc-8914-11ea-8b92-08002751a9d1:1 Auto_Position: 1 Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: Master_public_key_path: Get_master_public_key: 0 Network_Namespace: 1 row in set (0.00 sec)
SQL_Threadが止まっています。
エラーメッセージを読むとリレーログが読み取れないのが直接の原因のようです。 リレーログもしくはマスター側のバイナリログが壊れている可能性があるとのことなので、まずはリレーログから確認してみます。
[root@centos8-mysql:/mysql/mysql_home/data]# mysqlbinlog -vv --start-position=448 centos8-mysql-relay-bin.000004 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 404 #200506 23:30:19 server id 1 end_log_pos 125 CRC32 0xbc1a2019 Start: binlog v 4, server v 8.0.20 created 200506 23:30:19 BINLOG ' +8myXg8BAAAAeQAAAH0AAAAAAAQAOC4wLjIwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA CigBGSAavA== '/*!*/; # at 448 #200506 23:59:32 server id 1 end_log_pos 66984623 CRC32 0xb625fede GTID last_committed=84075 sequence_number=84076 rbr_only=yes original_committed_timestamp=1588777172737765 immediate_commit_timestamp=1588777172737765 transaction_length=246 /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; # original_commit_timestamp=1588777172737765 (2020-05-06 23:59:32.737765 JST) # immediate_commit_timestamp=1588777172737765 (2020-05-06 23:59:32.737765 JST) /*!80001 SET @@session.original_commit_timestamp=1588777172737765*//*!*/; /*!80014 SET @@session.original_server_version=80020*//*!*/; /*!80014 SET @@session.immediate_server_version=80020*//*!*/; SET @@SESSION.GTID_NEXT= 'f6145d93-89f9-11ea-bb4c-0800271d8d54:432208'/*!*/; ERROR: Could not read entry at offset 525: Error in log format or read error 1. ERROR: Found invalid event in binary log BEGIN /*added by mysqlbinlog */ /*!*/; 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*/;
下から8,9行目からバイナリログの中に読み取れないイベントがあるようです。
ということでマスター側のバイナリログを確認してみましょう。
[root@centos8-instance3:/var/lib/mysql/logs]# mysqlbinlog -vv --start-position=66984546 binlog.000011 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 196 #200506 23:30:19 server id 1 end_log_pos 125 CRC32 0xbc1a2019 Start: binlog v 4, server v 8.0.20 created 200506 23:30:19 # Warning: this binlog is either in use or was not closed properly. BINLOG ' +8myXg8BAAAAeQAAAH0AAAABAAQAOC4wLjIwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA CigBGSAavA== '/*!*/; # at 66984546 #200506 23:59:32 server id 1 end_log_pos 66984623 CRC32 0xb625fede GTID last_committed=84075 sequence_number=84076 rbr_only=yes original_committed_timestamp=1588777172737765 immediate_commit_timestamp=1588777172737765 transaction_length=246 /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; # original_commit_timestamp=1588777172737765 (2020-05-06 23:59:32.737765 JST) # immediate_commit_timestamp=1588777172737765 (2020-05-06 23:59:32.737765 JST) /*!80001 SET @@session.original_commit_timestamp=1588777172737765*//*!*/; /*!80014 SET @@session.original_server_version=80020*//*!*/; /*!80014 SET @@session.immediate_server_version=80020*//*!*/; SET @@SESSION.GTID_NEXT= 'f6145d93-89f9-11ea-bb4c-0800271d8d54:432208'/*!*/; # at 66984623 #200506 23:59:32 server id 1 end_log_pos 66984792 CRC32 0x2bacdf6f Transaction_Payload payload_size=136 compression_type=ZSTDuncompressed_size=188 # Start of compressed events! # at 66984792 #200506 23:59:32 server id 1 end_log_pos 66984792 CRC32 0x6ff5d676 Query thread_id=361 exec_time=0 error_code=0 SET TIMESTAMP=1588777172/*!*/; SET @@session.pseudo_thread_id=361/*!*/; 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 66984792 #200506 23:59:32 server id 1 end_log_pos 66984792 CRC32 0x52caabee Table_map: `repl_test`.`t1` mapped to number 147 # at 66984792 #200506 23:59:32 server id 1 end_log_pos 66984792 CRC32 0x63776fb9 Write_rows: table id 147 flags: STMT_END_F BINLOG ' 1NCyXhMBAAAANQAAAAAAAAAAAJMAAAAAAAEACXJlcGxfdGVzdAACdDEAAQMAAAEBAO6rylI= 1NCyXh4BAAAAKAAAAAAAAAAAAJMAAAAAAAEAAgAB/wACAAAAuW93Yw== '/*!*/; ### INSERT INTO `repl_test`.`t1` ### SET ### @1=2 /* INT meta=0 nullable=0 is_null=0 */ # at 66984792 #200506 23:59:32 server id 1 end_log_pos 66984792 CRC32 0x4df1dff4 Xid = 2602626 COMMIT/*!*/; # End of compressed events! 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*/;
思いっきりバイナリログトランザクション圧縮が有効になっている箇所であることが分かりますね。
というわけでMySQL8.0.20以降のサーバをSlaveとするときはMaster側のバイナリログトランザクション圧縮は無効にしておく必要があるということが分かりました。
最後に
バイナリログトランザクション圧縮を有効にすることでバイナリログを圧縮できる様子を見てきました。
ワークロードにもよると思いますが、デフォルトの圧縮レベルでもそれなりにストレージの節約になりそうです。
ただし、新しく追加された機能なのでバグなどがあるかもしれません。 本番環境に適用する場合は慎重に行う必要があります。
まずはサービスに影響のないバックアップ専用サーバなどで利用してみるのはいかがでしょうか。