MySQL の binlog について
実際に実行された更新系クエリの情報が記述されていてなんらかの理由によりデータが壊れた際の
データ復旧とかにも役にたつ。
binlog の format には以下の 3 種類ある
| フォーマットの種類 | 設定値(文字列) | 設定値(数字) | 備考 |
|---|---|---|---|
| ステートメントベース | STATEMENT | 1 | 実際に実行された SQL を記録 |
| 行ベース | ROW | 2 | 実際に変更された行のデータの情報を記録 |
| ミックス | MIXED | 0 | 基本的にはステートメントベースと同じで非決定性のクエリの際は行ベースと同じ形式のログを出力する |
ここら辺は DB server を構築する際にレプリケーションとかを考えると思うので
基本的には理解している内容だと思われます。
今回は binlog の中身を除いて実際にどうなってるの？というところを調べた。
実際にログを出力させて比べる
my.cnf
my.cnf を変更して binlog を出力するようにする
[mysqld] log_bin binlog_format = 1 # ステートメントベースのログを出力する
table
今回は下記の table を使用する
CREATE TABLE `users` ( `id` int(11) NOT NULL AUTO_INCREMENT, `name` varchar(255) DEFAULT NULL, `created_at` datetime NOT NULL, `updated_at` datetime NOT NULL, PRIMARY KEY (`id`) ) ENGINE=InnoDB;
使用する SQL
INSERT INTO users SET name = UUID(), created_at = NOW(), updated_at = NOW(); # 非決定性のクエリ INSERT INTO users SET name = "test", created_at = NOW(), updated_at = NOW();
ステートメントベース
$ mysqlbin mysql-bin.000001 # 一部抜粋 BEGIN /*!*/; # at 247 # at 279 #160612 14:56:46 server id 1 end_log_pos 279 CRC32 0xc624c39f Intvar SET INSERT_ID=20/*!*/; #160612 14:56:46 server id 1 end_log_pos 476 CRC32 0x6a52b700 Query thread_id=1 exec_time=0 error_code=0 use `db`/*!*/; SET TIMESTAMP=1465711006/*!*/; INSERT INTO users SET name = UUID(), created_at = NOW(), updated_at = NOW() /*!*/; # at 476 #160612 14:56:46 server id 1 end_log_pos 507 CRC32 0xf803a15e Xid = 21 COMMIT/*!*/; # at 507 #160612 14:56:53 server id 1 end_log_pos 634 CRC32 0xd617f39d Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1465711013/*!*/; BEGIN /*!*/; # at 634 # at 666 #160612 14:56:53 server id 1 end_log_pos 666 CRC32 0xe6f7f9d2 Intvar SET INSERT_ID=21/*!*/; #160612 14:56:53 server id 1 end_log_pos 863 CRC32 0x765b9f4d Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1465711013/*!*/; INSERT INTO users SET name = "test", created_at = NOW(), updated_at = NOW() /*!*/; # at 863 #160612 14:56:53 server id 1 end_log_pos 894 CRC32 0x828b94cf Xid = 22 COMMIT/*!*/;
確かに発行された SQL がそのまま出力されている
行ベース
$ mysqlbin mysql-bin.000002 # 一部抜粋 BEGIN /*!*/; # at 220 #160612 14:58:55 server id 1 end_log_pos 295 CRC32 0xa71dbfff Table_map: `db`.`users` mapped to number 83 # at 295 #160612 14:58:55 server id 1 end_log_pos 383 CRC32 0xb2425e19 Write_rows: table id 83 flags: STMT_END_F BINLOG ' H/pcVxMBAAAASwAAACcBAAAAAFMAAAAAAAEAGGJsb2dfc2FtcGxlc19kZXZlbG9wbWVudAAFdXNl cnMABAMPEhIE/QIAAAL/vx2n H/pcVx4BAAAAWAAAAH8BAAAAAFMAAAAAAAEAAgAE//AWAAAAJABiZjYwNTc0MC0zMDYyLTExZTYt OGQ2Zi0yZjg2MTFjNWE2ZjGZmZjut5mZmO63GV5Csg== '/*!*/; # at 383 #160612 14:58:55 server id 1 end_log_pos 414 CRC32 0xf290e6c8 Xid = 21 COMMIT/*!*/; # at 414 #160612 14:58:57 server id 1 end_log_pos 514 CRC32 0xc1908135 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1465711137/*!*/; BEGIN /*!*/; # at 514 #160612 14:58:57 server id 1 end_log_pos 589 CRC32 0x96559f32 Table_map: `db`.`users` mapped to number 83 # at 589 #160612 14:58:57 server id 1 end_log_pos 645 CRC32 0x56be64d2 Write_rows: table id 83 flags: STMT_END_F BINLOG ' IfpcVxMBAAAASwAAAE0CAAAAAFMAAAAAAAEAGGJsb2dfc2FtcGxlc19kZXZlbG9wbWVudAAFdXNl cnMABAMPEhIE/QIAAAIyn1WW IfpcVx4BAAAAOAAAAIUCAAAAAFMAAAAAAAEAAgAE//AXAAAABAB0ZXN0mZmY7rmZmZjuudJkvlY= '/*!*/; # at 645 #160612 14:58:57 server id 1 end_log_pos 676 CRC32 0x24726578 Xid = 22 COMMIT/*!*/;
な、なるほどわからん
もっと詳しく見れるようにオプションを追加する
$ mysqlbinlog -vvv --base64-output=DECODE-ROWS mysql-bin.000002 # 一部抜粋 BEGIN /*!*/; # at 220 #160612 14:58:55 server id 1 end_log_pos 295 CRC32 0xa71dbfff Table_map: `db`.`users` mapped to number 83 # at 295 #160612 14:58:55 server id 1 end_log_pos 383 CRC32 0xb2425e19 Write_rows: table id 83 flags: STMT_END_F ### INSERT INTO `db`.`users` ### SET ### @1=22 /* INT meta=0 nullable=0 is_null=0 */ ### @2='bf605740-3062-11e6-8d6f-2f8611c5a6f1' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */ ### @3='2016-06-12 14:58:55' /* DATETIME(0) meta=0 nullable=0 is_null=0 */ ### @4='2016-06-12 14:58:55' /* DATETIME(0) meta=0 nullable=0 is_null=0 */ # at 383 #160612 14:58:55 server id 1 end_log_pos 414 CRC32 0xf290e6c8 Xid = 21 COMMIT/*!*/; # at 414 #160612 14:58:57 server id 1 end_log_pos 514 CRC32 0xc1908135 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1465711137/*!*/; BEGIN /*!*/; # at 514 #160612 14:58:57 server id 1 end_log_pos 589 CRC32 0x96559f32 Table_map: `db`.`users` mapped to number 83 # at 589 #160612 14:58:57 server id 1 end_log_pos 645 CRC32 0x56be64d2 Write_rows: table id 83 flags: STMT_END_F ### INSERT INTO `db`.`users` ### SET ### @1=23 /* INT meta=0 nullable=0 is_null=0 */ ### @2='test' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */ ### @3='2016-06-12 14:58:57' /* DATETIME(0) meta=0 nullable=0 is_null=0 */ ### @4='2016-06-12 14:58:57' /* DATETIME(0) meta=0 nullable=0 is_null=0 */ # at 645 #160612 14:58:57 server id 1 end_log_pos 676 CRC32 0x24726578 Xid = 22 COMMIT/*!*/;
column 名が書かれているわけではなく @1 とか書かれてあるのだなぁ。
定義した table の column の順番通り @1 = id, @2 = name, @3 = created_at, @4 = updated_at という順番っぽい
UUID() も展開後の文字列が入っているのがわかる。
ミックス
$ mysqlbin mysql-bin.000003 # 一部抜粋 BEGIN /*!*/; # at 220 #160612 15:05:14 server id 1 end_log_pos 295 CRC32 0x3b4cb14b Table_map: `db`.`users` mapped to number 83 # at 295 #160612 15:05:14 server id 1 end_log_pos 383 CRC32 0x9905bb6a Write_rows: table id 83 flags: STMT_END_F BINLOG ' mvtcVxMBAAAASwAAACcBAAAAAFMAAAAAAAEAGGJsb2dfc2FtcGxlc19kZXZlbG9wbWVudAAFdXNl cnMABAMPEhIE/QIAAAJLsUw7 mvtcVx4BAAAAWAAAAH8BAAAAAFMAAAAAAAEAAgAE//AYAAAAJABhMTY1OWFmNi0zMDYzLTExZTYt OTc1Yi1hZjExNDczMDFkMDGZmZjxTpmZmPFOarsFmQ== '/*!*/; # at 383 #160612 15:05:14 server id 1 end_log_pos 414 CRC32 0x84766030 Xid = 21 COMMIT/*!*/; # at 414 #160612 15:05:16 server id 1 end_log_pos 541 CRC32 0xe4c9b7a8 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1465711516/*!*/; BEGIN /*!*/; # at 541 # at 573 #160612 15:05:16 server id 1 end_log_pos 573 CRC32 0x10f97ca5 Intvar SET INSERT_ID=25/*!*/; #160612 15:05:16 server id 1 end_log_pos 770 CRC32 0xd9adc7e3 Query thread_id=1 exec_time=0 error_code=0 use `db`/*!*/; SET TIMESTAMP=1465711516/*!*/; INSERT INTO users SET name = "test", created_at = NOW(), updated_at = NOW() /*!*/; # at 770 #160612 15:05:16 server id 1 end_log_pos 801 CRC32 0xa8cd90ff Xid = 22 COMMIT/*!*/;
本当にミックスされている
もっと詳しく見てみる
$ mysqlbinlog -vvv --base64-output=DECODE-ROWS mac-no-MacBook-Pro-bin.000003 # 一部抜粋 BEGIN /*!*/; # at 220 #160612 15:05:14 server id 1 end_log_pos 295 CRC32 0x3b4cb14b Table_map: `db`.`users` mapped to number 83 # at 295 #160612 15:05:14 server id 1 end_log_pos 383 CRC32 0x9905bb6a Write_rows: table id 83 flags: STMT_END_F ### INSERT INTO `db`.`users` ### SET ### @1=24 /* INT meta=0 nullable=0 is_null=0 */ ### @2='a1659af6-3063-11e6-975b-af1147301d01' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */ ### @3='2016-06-12 15:05:14' /* DATETIME(0) meta=0 nullable=0 is_null=0 */ ### @4='2016-06-12 15:05:14' /* DATETIME(0) meta=0 nullable=0 is_null=0 */ # at 383 #160612 15:05:14 server id 1 end_log_pos 414 CRC32 0x84766030 Xid = 21 COMMIT/*!*/; # at 414 #160612 15:05:16 server id 1 end_log_pos 541 CRC32 0xe4c9b7a8 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1465711516/*!*/; BEGIN /*!*/; # at 541 # at 573 #160612 15:05:16 server id 1 end_log_pos 573 CRC32 0x10f97ca5 Intvar SET INSERT_ID=25/*!*/; #160612 15:05:16 server id 1 end_log_pos 770 CRC32 0xd9adc7e3 Query thread_id=1 exec_time=0 error_code=0 use `db`/*!*/; SET TIMESTAMP=1465711516/*!*/; INSERT INTO users SET name = "test", created_at = NOW(), updated_at = NOW() /*!*/; # at 770 #160612 15:05:16 server id 1 end_log_pos 801 CRC32 0xa8cd90ff Xid = 22 COMMIT/*!*/;
非決定性のクエリの際は行ベースと同じ形式のログを出力することがわかった。
mysqlbinlog コマンドのオプション + SQL
よく使いそうなオプションをまとめる
$ mysqlbinlog -h host --read-from-remote-server mysql-bin.000001 # リモートサーバの binlog を見ることができる $ mysqlbinlog --start-datetime="2016-01-01 00:00:00" --stop-datetime="2016-01-01 12:00:00" mysql-bin.000001 # 日時を指定して binlog を見ることができる
binlog 情報を出力してくれる SQL をまとめる
mysql> SHOW GLOBAL VARIABLES LIKE 'binlog_format'; # binlog format を表示 +---------------+-------+ | Variable_name | Value | +---------------+-------+ | binlog_format | MIXED | +---------------+-------+ mysql> SHOW BINARY LOGS; # server の binlog 一覧を表示 +------------------+-----------+ | Log_name | File_size | +------------------+-----------+ | mysql-bin.000001 | 531 | | mysql-bin.000002 | 437 | | mysql-bin.000003 | 933 | +------------------+-----------+ mysql> SHOW BINLOG EVENTS; # binlog 内のイベントを表示 +------------------+-----+-------------+-----------+-------------+----------------------------------------------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +------------------+-----+-------------+-----------+-------------+----------------------------------------------------------------------------------------+ | mysql-bin.000001 | 4 | Format_desc | 1 | 120 | Server ver: 5.6.27-log, Binlog ver: 4 | | mysql-bin.000001 | 120 | Query | 1 | 247 | BEGIN | | mysql-bin.000001 | 247 | Intvar | 1 | 279 | INSERT_ID=16 | | mysql-bin.000001 | 279 | Query | 1 | 477 | use `db`; insert into users set name = UUID(), created_at = NOW(), updated_at = NOW() | | mysql-bin.000001 | 477 | Xid | 1 | 508 | COMMIT /* xid=24 */ | | mysql-bin.000001 | 508 | Stop | 1 | 531 | | +------------------+-----+-------------+-----------+-------------+----------------------------------------------------------------------------------------+
最後に
ということで今回は MySQL の binlog についての format による違いを確認してみました。
binlog にどのような情報が記述されているか最低限覚えておくと
ここぞという時に役に立つかと思います
