まっしろけっけ

めもてきなやーつ

MySQL の binlog について調べたメモ

mysql web 開発 プログラミング ツール

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 にどのような情報が記述されているか最低限覚えておくと
ここぞという時に役に立つかと思います