MySQL5.6からrowベースのレプリケーションを使用している場合でもステートメント(クエリ)をコメントとしてバイナリログに記録するオプション(binlog_rows_query_log_events)が追加されています。
このオプションを利用することでrowベースでレプリケーションされたクエリが確認し易くなります。
binlog_rows_query_log_eventsが無効な場合
mysqlbinlogコマンドに-vオプションを使う事である程度は把握が可能でした。以下例はbinlog_rows_query_log_eventsが無効な場合の表示例です。
テーブル定義と設定
mysql> show create table test\G
*************************** 1. row ***************************
Table: test
Create Table: CREATE TABLE `test` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`message` varchar(255) DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)
mysql> select @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| ROW |
+-----------------+
1 row in set (0.00 sec)
mysql> select @@binlog_rows_query_log_events;
+--------------------------------+
| @@binlog_rows_query_log_events |
+--------------------------------+
| 0 |
+--------------------------------+
1 row in set (0.00 sec)
mysql>
INSERTの実行
mysql> insert into test(message) values ('ROW,OFF');
Query OK, 1 row affected (0.24 sec)
mysql>
mysqlbinlogコマンドで確認
MySQL5.6環境で確認しているため、以下のようにmysqlbinlogコマンドを実行しています。
# mysqlbinlog -vv --base64-output=DECODE-ROWS -u root -R -h 127.0.0.1 --stop-never
INSERTの実行で出力された内容は以下になります。
# at 1854 #130216 17:05:21 server id 137 end_log_pos 1926 CRC32 0x69336912 Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1361001921/*!*/; BEGIN /*!*/; # at 1926 #130216 17:05:21 server id 137 end_log_pos 1976 CRC32 0x8a9e741a Table_map: `test`.`test` mapped to number 71 # at 1976 #130216 17:05:21 server id 137 end_log_pos 2025 CRC32 0xe888825f Write_rows: table id 71 flags: STMT_END_F ### INSERT INTO `test`.`test` ### SET ### @1=1 /* INT meta=0 nullable=0 is_null=0 */ ### @2='ROW,OFF' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */ # at 2025 #130216 17:05:21 server id 137 end_log_pos 2056 CRC32 0x402bb475 Xid = 88 COMMIT/*!*/;
正直、視認性は良くありません。UPDATEだったり列の多いテーブルだったりだと更に縦に長い出力となります。
binlog_rows_query_log_eventsが有効な場合
パラメータの変更点はbinlog_rows_query_log_eventsが有効になっただけです。
mysql> select @@binlog_rows_query_log_events; +--------------------------------+ | @@binlog_rows_query_log_events | +--------------------------------+ | 1 | +--------------------------------+ 1 row in set (0.00 sec) mysql>
INSERTの実行
mysql> insert into test(message) values ('ROW,ON');
Query OK, 1 row affected (0.00 sec)
mysql>
mysqlbinlogコマンドで確認
# at 2056
#130216 17:14:16 server id 137 end_log_pos 2128 CRC32 0xd269d2b1 Query thread_id=18 exec_time=0 error_code=0
SET TIMESTAMP=1361002456/*!*/;
BEGIN
/*!*/;
# at 2128
#130216 17:14:16 server id 137 end_log_pos 2195 CRC32 0xe407772a Rows_query
# insert into test(message) values ('ROW,ON')
# at 2195
#130216 17:14:16 server id 137 end_log_pos 2245 CRC32 0x0a47bd84 Table_map: `test`.`test` mapped to number 71
# at 2245
#130216 17:14:16 server id 137 end_log_pos 2293 CRC32 0x8be81270 Write_rows: table id 71 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
### @1=2 /* INT meta=0 nullable=0 is_null=0 */
### @2='ROW,ON' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */
# at 2293
#130216 17:14:16 server id 137 end_log_pos 2324 CRC32 0x7fadbea3 Xid = 105
COMMIT/*!*/;以下のように発行したクエリがコメントとして記載されていることがわかります。
# insert into test(message) values ('ROW,ON')デメリットとしては当然記録される情報が増えるため、バイナリログのサイズが増加することです。binlog_format=mixedの場合はめったにrowで記録されることは無いので影響は少ないのでは、と考えています。
binlog_format=rowの場合はサイズがそれなりに増加することが考えられるので5.6系であればbinlog_row_imageパラメータと合わせて設定を検討するのが良いかと。
マニュアルに記載があった内容を確認するために5.6.10 -> 5.5.30でレプリケーションを組んでみたところ、binlog_checksum=NONE、binlog_format=mixedとしたらROWベースでレプリケーションされるようなクエリを実行した際、以下のようにレプリケーションエラーとなりました。
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, 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.
また、エラーとなった際のリレーログを5.5.30のmysqlbinlogコマンドで確認したところ以下のような出力がありました。
BEGIN /*!*/; # at 342 ERROR: Error in Log_event::read_log_event(): 'Sanity check failed', data_len: 51, event_type: 30 ERROR: Could not read entry at offset 391: Error in log format or read error. DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */;
binlog_rows_query_log_eventsがOFFだろうと上記のエラーとなったため、binlog_rows_query_log_eventsによるエラーが発生するか、発生する場合はどういった内容になるかは確認出来ていません。
メッセージからはログのフォーマットが変わった事による物のようなのでパラメータで直せるか調べてましたが今の所分からず。
なんらかの理由により5.6 -> 5.5等でレプリケーション構成を取る必要がある場合はbinlog_format=statementにしないと予期しないレプリケーションエラーに遭遇するかも可能性があります。statementにする場合は当然rowでないとレプリケーション的に安全でないクエリがスレーブに送られる場合があるので使用するクエリには注意する必要があります。<以下追記>
一応互換性を保つためのパラメータがあったもよう。
んでドキュメントに載ってないと。
log_bin_use_v1_row_eventsを有効にして試したら一律rowの場合にエラーになるわけじゃないようです。でもtimestamp型だとエラーになるのでその兼ね合いもあってまだドキュメントに載ってないのかもしれません。
一応エラー内容
Last_SQL_Error: Column 2 of table 'test.test2' cannot be converted from type '<unknown type>' to type 'timestamp'
<更に追記>
log_bin_use_v1_row_eventsを有効にしてレプリケーションエラーとならないケースでbinlog_rows_query_log_eventsを有効にしてROWベースでレプリケーションしたところ同じエラーになりました。
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, 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.
