この記事は最終更新日から1年以上が経過しています。

バイナリログのフォーマットについて

今回もMySQL勉強ネタ。インプットしたことはアウトプットすることでしっかり自分の頭の中で整理されます。
まだまだアウトプット力が足りないですが、これも訓練、しっかりと継続して自分のものにしていきたいと思います。

「log-bin[=ファイル名]」で出力されるMySQLのバイナリログ。
ログのフォーマットにはMySQL5.1から”行ベース”が追加されましたとのこと。

ふむふむ。。。で、「行ベース」ってなんスか??

よくわからなかったので、調べてみました。

そもそもバイナリログとはなにか

バイナリログとは更新クエリを記録するログファイルのことです。
更新クエリをログとして持っておくと何が嬉しいのかって、そのログを使ってデータをリカバリーすることができたり、そのログデータを受け取るようにしてレプリケーション構成を構築できたりします。

バイナリログはmy.cnfに以下の様に記載することで出力されるようになります。

[mysqld]
log-bin=mysql-bin

log-binに出力するファイル名を指定します。ファイルはdatadirの中に出力されます。

ログフォーマットの種類

ログフォーマットの種類には以下の設定が可能です。

フォーマットの種類 設定値(数字・文字列どちらでも可)
ステートメントベース STATEMENT 1
行ベース ROW 2
ミックス MIXED 0

「ステートメントベース」とは実行したステートメント(SQL文)をバイナリログに記載します。

「行ベース」とは行の変更だけがバイナリログに記載されます。

「ミックス」は基本的にステートメントベースと同じ動作をしますが、特定の場合に行ベースに切り替わります。
特定の条件とは、UDFやUUID()を使用した時、Clusterレプリケーションを使用した時です。

では実際にそれぞれのフォーマットがどのようにログに出力されるのか確認していきます。

前提条件

今回は少しボリュームのあるデータを扱いたいので、こちらの「world database」を利用します。このデータを「world_data」データベースを作成し、こちらに流し込みます。

CREATE DATABASE world_data;

データ更新様に「city」テーブルにカラムを追加しておきます。

ALTER TABLE city ADD `c1` VARCHAR(50);

また、バイナリログの確認には「mysqlbinlog」コマンドを使用します。
検証環境のmy.cnfには「client」グループに”default-character-set = utf8mb4″の設定が入いるため、そのまま「mysqlbinlog」コマンドを使用した場合以下のようなエラーが表示されてしまいました。

./bin/mysqlbinlog: unknown variable 'default-character-set=utf8mb4'

こちらのエラーが表示された場合は「–no-defaults」オプションをつけて「mysqlbinlog」コマンドを使用します。

./bin/mysqlbinlog  --no-defaults ../mysql_data/mysql-bin.000014

STATEMENT

まずはステートメントベースのバイナリログを確認します。

mysql> FLUSH LOGS;
Query OK, 0 rows affected (0.05 sec)

mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: mysql-bin.000015
         Position: 120
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: 
1 row in set (0.01 sec)

mysql> SET binlog_format = 1; 
Query OK, 0 rows affected (0.01 sec)

まず「FLUSH LOGS」でログをローテートさせ新しいファイルに作成ログが書き込まれるようにします。新しいファイル名は「SHOW MASTER STATUS」で確認できます。
その後「SET binlog_format = 1」でバイナリログのフォーマットをステートメントベースに変更しています。

現在のフォーマットの種類は「SHOW VARIABLES LIKE “binlog_format”」で確認できます。

mysql> SHOW VARIABLES LIKE "binlog_format";
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+
1 row in set (0.01 sec)

では、まず以下のSQLを実行します。

mysql> UPDATE City SET c1 = 'test1' WHERE CountryCode LIKE 'JPN';
Query OK, 248 rows affected (0.07 sec)
Rows matched: 248  Changed: 248  Warnings: 0

248行が更新されました。この時バイナリログには以下の様に記載されます。

# at 120
#140409 12:24:45 server id 1  end_log_pos 211 CRC32 0x63542ae2 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397013885/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 211
#140409 12:24:45 server id 1  end_log_pos 354 CRC32 0xfa74dee3 	Query	thread_id=3	exec_time=0	error_code=0
use `world_data`/*!*/;
SET TIMESTAMP=1397013885/*!*/;
UPDATE City SET c1 = 'test1' WHERE CountryCode LIKE 'JPN'
/*!*/;
# at 354
#140409 12:24:45 server id 1  end_log_pos 385 CRC32 0xeda66fae 	Xid = 5422
COMMIT/*!*/;

上記18行目で同じSQLが出力されています。これがステートメントベースのログフォーマットです。

再度全く同じSQLを流してみます。

mysql> UPDATE City SET c1 = 'test1' WHERE CountryCode LIKE 'JPN';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 248  Changed: 0  Warnings: 0

UPDATE文は実行されましたが、同じ内容の変更でしたので、変更された行はありませんでした。
しかしこの場合も、

# at 385
#140409 12:27:10 server id 1  end_log_pos 476 CRC32 0x326673f9 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014030/*!*/;
BEGIN
/*!*/;
# at 476
#140409 12:27:10 server id 1  end_log_pos 619 CRC32 0xa38d5177 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014030/*!*/;
UPDATE City SET c1 = 'test1' WHERE CountryCode LIKE 'JPN'
/*!*/;
# at 619
#140409 12:27:10 server id 1  end_log_pos 650 CRC32 0xd203aec2 	Xid = 5423
COMMIT/*!*/;

のようにステートメントベースのログフォーマットではログが出力されます。

ROW

続いて行ベースのフォーマットを確認します。行の変更がバイナリログに記載されます。

まずステートメントベースの時と同様にログをローテーションさせモードを切り替えます。

mysql> FLUSH LOGS;
Query OK, 0 rows affected (0.05 sec)

mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: mysql-bin.000016
         Position: 120
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: 
1 row in set (0.01 sec)

mysql> SET binlog_format = 2; 
Query OK, 0 rows affected (0.00 sec)

早速更新クエリを投げてみます。

mysql> UPDATE City SET c1 = 'test2' WHERE CountryCode LIKE 'JPN';
Query OK, 248 rows affected (0.01 sec)
Rows matched: 248  Changed: 248  Warnings: 0

バイナリログ出力の結果が以下です。

# at 120
#140409 12:31:30 server id 1  end_log_pos 198 CRC32 0x82077fd1 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014290/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 198
#140409 12:31:30 server id 1  end_log_pos 264 CRC32 0x8a6b660f 	Table_map: `world_data`.`city` mapped to number 79
# at 264
#140409 12:31:30 server id 1  end_log_pos 8418 CRC32 0x7cb0ea64 	Update_rows: table id 79
# at 8418
#140409 12:31:30 server id 1  end_log_pos 16614 CRC32 0x68e277fd 	Update_rows: table id 79
# at 16614
#140409 12:31:30 server id 1  end_log_pos 17498 CRC32 0xaf797757 	Update_rows: table id 79 flags: STMT_END_F

BINLOG '
Er9EUxMBAAAAQgAAAAgBAAAAAE8AAAAAAAEACndvcmxkX2RhdGEABGNpdHkABgP+/v4DDwj+I/4D
/hQyACAPZmuK
Er9EUx8BAAAA2h8AAOIgAAAAAE8AAAAAAAAAAgAG///A/AUAAAVUb2t5bwNKUE4IVG9reW8tdG/G
xHkABXRlc3QxwPwFAAAFVG9reW8DSlBOCFRva3lvLXRvxsR5AAV0ZXN0MsD9BQAAE0pva29oYW1h
IFtZb2tvaGFtYV0DSlBOCEthbmFnYXdhSvUyAAV0ZXN0McD9BQAAE0pva29oYW1hIFtZb2tvaGFt
YV0DSlBOCEthbmFnYXdhSvUyAAV0ZXN0MsD+BQAABU9zYWthA0pQTgVPc2FrYVqbJwAFdGVzdDHA
/gUAAAVPc2FrYQNKUE4FT3Nha2FamycABXRlc3QywP8FAAAGTmFnb3lhA0pQTgVBaWNoaYjfIAAF
dGVzdDHA/wUAAAZOYWdveWEDSlBOBUFpY2hpiN8gAAV0ZXN0MsAABgAAB1NhcHBvcm8DSlBOCEhv
a2thaWRvplMbAAV0ZXN0McAABgAAB1NhcHBvcm8DSlBOCEhva2thaWRvplMbAAV0ZXN0MsABBgAA
BUtpb3RvA0pQTgVLeW90b9ZOFgAFdGVzdDHAAQYAAAVLaW90bwNKUE4FS3lvdG/WThYABXRlc3Qy
wAIGAAAES29iZQNKUE4FSHlvZ2/zvhUABXRlc3QxwAIGAAAES29iZQNKUE4FSHlvZ2/zvhUABXRl
c3QywAMGAAAHRnVrdW9rYQNKUE4HRnVrdW9rYdv2EwAFdGVzdDHAAwYAAAdGdWt1b2thA0pQTgdG
dWt1b2th2/YTAAV0ZXN0MsAEBgAACEthd2FzYWtpA0pQTghLYW5hZ2F3YU+TEgAFdGVzdDHABAYA
-- 中略 --
c2hpbWF0c3V5YW1hA0pQTgdTYWl0YW1hnmwBAAV0ZXN0MsDrBgAAB0tpbWl0c3UDSlBOBUNoaWJh
IGwBAAV0ZXN0McDrBgAAB0tpbWl0c3UDSlBOBUNoaWJhIGwBAAV0ZXN0MsDsBgAAB0lzYWhheWED
SlBOCE5hZ2FzYWtpgmsBAAV0ZXN0McDsBgAAB0lzYWhheWEDSlBOCE5hZ2FzYWtpgmsBAAV0ZXN0
MsDtBgAABkthbnVtYQNKUE4HVG9jaGlnaX1rAQAFdGVzdDHA7QYAAAZLYW51bWEDSlBOB1RvY2hp
Z2l9awEABXRlc3QywO4GAAAJSXp1bWlzYW5vA0pQTgVPc2FrYadpAQAFdGVzdDHA7gYAAAlJenVt
aXNhbm8DSlBOBU9zYWthp2kBAAV0ZXN0MsDvBgAAB0thbWVva2EDSlBOBUt5b3Rv7mgBAAV0ZXN0
McDvBgAAB0thbWVva2EDSlBOBUt5b3Rv7mgBAAV0ZXN0MsDwBgAABk1vYmFyYQNKUE4FQ2hpYmEQ
ZgEABXRlc3QxwPAGAAAGTW9iYXJhA0pQTgVDaGliYRBmAQAFdGVzdDLA8QYAAAZOYXJpdGEDSlBO
BUNoaWJhTmUBAAV0ZXN0McDxBgAABk5hcml0YQNKUE4FQ2hpYmFOZQEABXRlc3QywPIGAAALS2Fz
aGl3YXpha2kDSlBOB05paWdhdGFdZAEABXRlc3QxwPIGAAALS2FzaGl3YXpha2kDSlBOB05paWdh
dGFdZAEABXRlc3QywPMGAAAHVHN1eWFtYQNKUE4HT2theWFtYSJkAQAFdGVzdDHA8wYAAAdUc3V5
YW1hA0pQTgdPa2F5YW1hImQBAAV0ZXN0Mld3ea8=
'/*!*/;
# at 17498
#140409 12:31:30 server id 1  end_log_pos 17529 CRC32 0xeba80da1 	Xid = 5427
COMMIT/*!*/;

まず、行ベースで出力されるログはbase64化されたものになります。
そして更新された248行文のログが出力されていますので、大量のログが出力されています。

こちらも同じSQLを流してみます。

mysql> UPDATE City SET c1 = 'test2' WHERE CountryCode LIKE 'JPN';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 248  Changed: 0  Warnings: 0

UPDATE文は実行されましたが、更新行がなかったためバイナリログには何も出力されませんでした。
これが行ベースフォーマットでのバイナリログになります。

MIXED

最後にミックスフォーマットのバイナリログを確認します。ミックスフォーマットはその名の通り「ステートメントベース」「行ベース」両方のログが出力されるのですが、基本的にはステートメントベースになります。

mysql> FLUSH LOGS;
Query OK, 0 rows affected (0.04 sec)

mysql> SHOW MASTER STATUS\G
*************************** 1. row ***************************
             File: mysql-bin.000017
         Position: 120
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: 
1 row in set (0.00 sec)

mysql> SET binlog_format = 0;
Query OK, 0 rows affected (0.00 sec)

更新SQLを実行します。

mysql> UPDATE City SET c1 = 'test3' WHERE CountryCode LIKE 'JPN';
Query OK, 248 rows affected (0.00 sec)
Rows matched: 248  Changed: 248  Warnings: 0

ステートメントベースの時と同じ形のログが出力されます。

# at 120
#140409 12:38:05 server id 1  end_log_pos 211 CRC32 0x40cc2c23 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014685/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 211
#140409 12:38:05 server id 1  end_log_pos 354 CRC32 0xa02f616d 	Query	thread_id=3	exec_time=0	error_code=0
use `world_data`/*!*/;
SET TIMESTAMP=1397014685/*!*/;
UPDATE City SET c1 = 'test3' WHERE CountryCode LIKE 'JPN'
/*!*/;
# at 354
#140409 12:38:05 server id 1  end_log_pos 385 CRC32 0xaef36bc9 	Xid = 5432
COMMIT/*!*/;

同じSQLを実行します。

mysql> UPDATE City SET c1 = 'test3' WHERE CountryCode LIKE 'JPN';
Query OK, 0 rows affected (0.01 sec)
Rows matched: 248  Changed: 0  Warnings: 0

こちらもステートメントベースと同様に、行の更新がなくてもバイナリログには出力されます。

# at 385
#140409 12:39:35 server id 1  end_log_pos 476 CRC32 0x786d091a 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014775/*!*/;
BEGIN
/*!*/;
# at 476
#140409 12:39:35 server id 1  end_log_pos 619 CRC32 0x76ea601c 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014775/*!*/;
UPDATE City SET c1 = 'test3' WHERE CountryCode LIKE 'JPN'
/*!*/;
# at 619
#140409 12:39:35 server id 1  end_log_pos 650 CRC32 0x917b21c3 	Xid = 5433
COMMIT/*!*/;

ここまではステートメントベースと全く同じ動きとなっています。では、どのようなときに行ベースで出力されるのでしょうか。
それは冒頭の方でも書いていますが、「UDFやUUID()を使用した時、Clusterレプリケーションを使用した時」になります。

あえてUUID関数を使って行を更新してみましょう。

mysql> UPDATE City SET c1 = UUID() WHERE CountryCode LIKE 'JPN';
Query OK, 248 rows affected (0.02 sec)
Rows matched: 248  Changed: 248  Warnings: 0

以下バイナリログの出力結果です。

# at 650
#140409 12:41:40 server id 1  end_log_pos 728 CRC32 0xb8290145 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1397014900/*!*/;
BEGIN
/*!*/;
# at 728
#140409 12:41:40 server id 1  end_log_pos 794 CRC32 0xabae19d8 	Table_map: `world_data`.`city` mapped to number 79
# at 794
#140409 12:41:40 server id 1  end_log_pos 8973 CRC32 0xf8bf45f4 	Update_rows: table id 79
# at 8973
#140409 12:41:40 server id 1  end_log_pos 17098 CRC32 0x1252420c 	Update_rows: table id 79
# at 17098
#140409 12:41:40 server id 1  end_log_pos 25219 CRC32 0xb1e27e7b 	Update_rows: table id 79
# at 25219
#140409 12:41:40 server id 1  end_log_pos 25752 CRC32 0x1d8cbe8f 	Update_rows: table id 79 flags: STMT_END_F

BINLOG '
dMFEUxMBAAAAQgAAABoDAAAAAE8AAAAAAAEACndvcmxkX2RhdGEABGNpdHkABgP+/v4DDwj+I/4D
/hQyACDYGa6r
dMFEUx8BAAAA8x8AAA0jAAAAAE8AAAAAAAAAAgAG///A/AUAAAVUb2t5bwNKUE4IVG9reW8tdG/G
xHkABXRlc3QzwPwFAAAFVG9reW8DSlBOCFRva3lvLXRvxsR5ACRkYzUxYmNmMC1iZjk4LTExZTMt
OWY5YS00NzQ1ODNjMDNjZWHA/QUAABNKb2tvaGFtYSBbWW9rb2hhbWFdA0pQTghLYW5hZ2F3YUr1
MgAFdGVzdDPA/QUAABNKb2tvaGFtYSBbWW9rb2hhbWFdA0pQTghLYW5hZ2F3YUr1MgAkZGM1MWQw
ZGMtYmY5OC0xMWUzLTlmOWEtNDc0NTgzYzAzY2VhwP4FAAAFT3Nha2EDSlBOBU9zYWthWpsnAAV0
ZXN0M8D+BQAABU9zYWthA0pQTgVPc2FrYVqbJwAkZGM1MWRkMDItYmY5OC0xMWUzLTlmOWEtNDc0
NTgzYzAzY2VhwP8FAAAGTmFnb3lhA0pQTgVBaWNoaYjfIAAFdGVzdDPA/wUAAAZOYWdveWEDSlBO
BUFpY2hpiN8gACRkYzUyMDAxNi1iZjk4LTExZTMtOWY5YS00NzQ1ODNjMDNjZWHAAAYAAAdTYXBw
b3JvA0pQTghIb2trYWlkb6ZTGwAFdGVzdDPAAAYAAAdTYXBwb3JvA0pQTghIb2trYWlkb6ZTGwAk
ZGM1MjAyOTYtYmY5OC0xMWUzLTlmOWEtNDc0NTgzYzAzY2VhwAEGAAAFS2lvdG8DSlBOBUt5b3Rv
1k4WAAV0ZXN0M8ABBgAABUtpb3RvA0pQTgVLeW90b9ZOFgAkZGM1MjA0YzYtYmY5OC0xMWUzLTlm
-- 中略 --
dMFEUx8BAAAAFQIAAJhkAAAAAE8AAAAAAAEAAgAG///A7wYAAAdLYW1lb2thA0pQTgVLeW90b+5o
AQAFdGVzdDPA7wYAAAdLYW1lb2thA0pQTgVLeW90b+5oAQAkZGM1MmM4YWMtYmY5OC0xMWUzLTlm
OWEtNDc0NTgzYzAzY2VhwPAGAAAGTW9iYXJhA0pQTgVDaGliYRBmAQAFdGVzdDPA8AYAAAZNb2Jh
cmEDSlBOBUNoaWJhEGYBACRkYzUyYzliYS1iZjk4LTExZTMtOWY5YS00NzQ1ODNjMDNjZWHA8QYA
AAZOYXJpdGEDSlBOBUNoaWJhTmUBAAV0ZXN0M8DxBgAABk5hcml0YQNKUE4FQ2hpYmFOZQEAJGRj
NTJjYTMyLWJmOTgtMTFlMy05ZjlhLTQ3NDU4M2MwM2NlYcDyBgAAC0thc2hpd2F6YWtpA0pQTgdO
aWlnYXRhXWQBAAV0ZXN0M8DyBgAAC0thc2hpd2F6YWtpA0pQTgdOaWlnYXRhXWQBACRkYzUyY2Fh
YS1iZjk4LTExZTMtOWY5YS00NzQ1ODNjMDNjZWHA8wYAAAdUc3V5YW1hA0pQTgdPa2F5YW1hImQB
AAV0ZXN0M8DzBgAAB1RzdXlhbWEDSlBOB09rYXlhbWEiZAEAJGRjNTJjYjE4LWJmOTgtMTFlMy05
ZjlhLTQ3NDU4M2MwM2NlYY++jB0=
'/*!*/;
# at 25752
#140409 12:41:40 server id 1  end_log_pos 25783 CRC32 0x6771cc73 	Xid = 5434
COMMIT/*!*/;

行ベースと同様のフォーマットで出力されました。

まとめ

以上の結果からそれぞれのフォーマットの違いをまとめてみました。

STATEMENT

実行したSQL文でバイナリログが記載される。
バイナリログはコミットと同時に書き込まれるため、レプリケーションなどのスレーブサーバーではSQLによっては反映に遅延が発生することが有る。
UUIDを使用した場合はレプリケーションでマスターとスレーブの値の相違が発生する。
デフォルトではこの設定。

ROW

行の更新がbase64化されて出力される。
STATEMENTはSQL文が記載されるので、どこでどのような処理をしたか見てわかるが、ROWだとわからない。
行ベースの更新なのでスレーブ等への更新は早いが、データ量が大きくなってしまうので、ストレージ容量、レプリケーションの場合のネットワーク帯域等を気にしなければならない。

MIXED

基本的にはSTATEMENTと同じ形式の出力。
UDFやUUID()を使用した時、Clusterレプリケーションを使用した時にはROWで出力される。

スレーブへの更新タイミングが重要でなければ「STATEMENT」のままで大丈夫かと思いますが、「MIXED」に変更しておくのが無難でしょう。また、スレーブへの更新タイミングが重要な場合や、ストレージ容量・ネットワーク帯域が十分に確保されている場合は「ROW」が良いかと思います。

コメントを残す