mysqlのバイナリログのフォーマットを調べた

memo

とあるアプリケーションをレンタルサーバーに設置しようとした際に、
MariaDBが以下のようなエラーを吐いていた。

1
2
3
4
Unsafe statement written to the binary log using statement format
since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it
invokes a trigger or a stored function that inserts into an
AUTO_INCREMENT column. Inserted values cannot be logged correctly.

バイナリログフォーマットがSTATEMENTだと安全でないのでよろしくないらしい。
STATEMENTだと安全でないということはどういうことか。少し試してみた。

バイナリログについて

RDBMSでいうところのトランザクションログをMySQLではバイナリログという。

バイナリログにはMySQLにおいてデータベースに対して

  • トランザクションの開始および終了
  • 値の挿入(INSERT)、値の更新(UPDATE)、削除(DELETE)
  • テーブル、インデックスの作成削除

の履歴が保持されている。

トランザクションログはRDBMSによって異なり、以下に大別される。

トランザクションログ 概要
論理ロギング データベースに対する論理動作(SQL文)の変更履歴を管理
物理ロギング 変更があったデータの変更前のイメージを管理

バイナリログはデフォルトでは生成されないのでmy.cnfに設定を追加する必要がある。

1
2
3
4
5
# grep my.cnf
mysql --help | grep my.cnf
touch /usr/local/etc/my.cnf

cat /usr/local/etc/my.cnf
1
2
[mysqld]
log-bin=mysql-bin

設定することにより、/usr/local/var/mysql/mysql-bin.000001 のようにログファイルが生成される。
再起動などすると /usr/local/var/mysql/mysql-bin.000002 と新たなログファイルが生成される。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
ls /usr/local/var/mysql/

mysql-bin.000001

mysql.server restart
Shutting down MySQL
. SUCCESS!
Starting MySQL
. SUCCESS!

ls /usr/local/var/mysql/

mysql-bin.000001
mysql-bin.000002

存在するログファイルは /usr/local/var/mysql/mysql-bin.index にリストアップされている。
ということで rm などでログだけ消すと次回起動時にエラーになる。mysql-bin.indexからも削除する必要が有る。

また、ログファイルは溜まっていく一方なので自動削除するためにmy.cnfに設定を追加。
expire_log_days でログを保持する期間を追加。(初期値は0で削除しない)
7日間保持するなら、以下のような感じ。

1
2
3
[mysqld]
log-bin=mysql-bin
expire_log_days = 7

バイナリログのフォーマット

バイナリログのフォーマットは3種類あり、それぞれ以下のようになっている。

フォーマット 特徴
STATEMENT 実行されたSQLに基づいてロギング
ROW 行ベースに基づきロギング
MIXED 基本はSTATEMENTだが特定の条件では行ベースでロギングする

おそらくレンタルサーバーとかだと、STATEMENTに設定されていることが多いんじゃないかなと思う。

それぞれの挙動を適当なテーブルを作り試してみる。

1
2
3
4
5
6
7
8
9
create database test;
create table personal(id int auto_increment, name varchar(10),index(id));
SHOW FULL COLUMNS FROM personal;
+-------+-------------+-----------------+------+-----+---------+----------------+---------------------------------+---------+
| Field | Type        | Collation       | Null | Key | Default | Extra          | Privileges                      | Comment |
+-------+-------------+-----------------+------+-----+---------+----------------+---------------------------------+---------+
| id    | int(11)     | NULL            | NO   | MUL | NULL    | auto_increment | select,insert,update,references |         |
| name  | varchar(10) | utf8_general_ci | YES  |     | NULL    |                | select,insert,update,references |         |
+-------+-------------+-----------------+------+-----+---------+----------------+---------------------------------+---------+

Statement base

デフォルトのフォーマット(MySQL5.6まで)。データやテーブル変更の実際に実行されたSQL文をログとして記録する。
Non-Deterministicということで、Unsafeとなる。
つまりレプリケーションのスレーブ側のサーバーでログを元に同じSQLを実行しても
同じになるとは限らないため。

https://dev.mysql.com/doc/refman/5.6/ja/replication-sbr-rbr.html

実際にtableに値を追加してバイナリログを確認していく。

insertしてみる

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
# set statement
SET binlog_format = 'STATEMENT';

SHOW variables LIKE "binlog_format";
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+

FLUSH LOGS;
Query OK, 0 rows affected (0.07 sec)

 SHOW MASTER STATUS;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000001 |      120 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
# insert
INSERT INTO personal(name) VALUES('tom');

# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001

BEGIN
/*!*/;
# at 199
# at 231
#151205 20:54:19 server id 1  end_log_pos 231 CRC32 0x40b495c3  Intvar
SET INSERT_ID=1/*!*/;
#151205 20:54:19 server id 1  end_log_pos 345 CRC32 0x9668f30b  Query   thread_id=1 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1449316459/*!*/;
INSERT INTO personal(name) VALUES('tom')
/*!*/;
# at 345
#151205 20:54:19 server id 1  end_log_pos 376 CRC32 0x2247f106  Xid = 8
COMMIT/*!*/;

ログファイルはそれぞれ以下のような項目がある。

項目 内容
at バイナリファイル内でのオフセット
server id ステートメントが実行されたサーバー
end_log_pos 次のイベントが開始される位置
thread_id 実行したスレッド
exec_time 実行時間
error_code イベントの実行結果(0はエラーなし)

続いてupdateしてみる

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
# update
UPDATE personal SET name='tommy' WHERE id = 1;

# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001

# at 376
#151205 20:56:39 server id 1  end_log_pos 455 CRC32 0x852a4061  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449319780/*!*/;
BEGIN
/*!*/;
# at 455
#151205 20:56:39 server id 1  end_log_pos 574 CRC32 0xc5128701  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449319780/*!*/;
UPDATE personal SET name='tommy' WHERE id = 1
/*!*/;
# at 574
#151205 20:56:39 server id 1  end_log_pos 605 CRC32 0x9217061a  Xid = 9
COMMIT/*!*/;

変更のないように同じ値でupdateを試してみると

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# update
UPDATE personal SET name='tommy' WHERE id = 1;

# at 605
#151205 20:58:12 server id 1  end_log_pos 684 CRC32 0x7bcd8a62  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449319820/*!*/;
BEGIN
/*!*/;
# at 684
#151205 20:58:12 server id 1  end_log_pos 803 CRC32 0x132e24fc  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449319820/*!*/;
UPDATE personal SET name='tommy' WHERE id = 1
/*!*/;
# at 803
#151205 20:58:12 server id 1  end_log_pos 834 CRC32 0xb3d62bb8  Xid = 10
COMMIT/*!*/;

STATEMENTは実行されたSQL文をロギングするので、値に変更がなくてもログが出力される。

Row base

つづいてROWフォーマットで同じように試してみる。

1
2
3
4
5
6
7
8
SET binlog_format = 'ROW';
SHOW variables LIKE "binlog_format";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW   |
+---------------+-------+
1 row in set (0.00 sec)

データをinsertする。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
# insert
INSERT INTO personal(name) VALUES('tom');

# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001

# at 580
#151205 21:08:25 server id 1  end_log_pos 652 CRC32 0x629d7346  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449321070/*!*/;
BEGIN
/*!*/;
# at 652
#151205 21:08:25 server id 1  end_log_pos 706 CRC32 0xb60de956  Table_map: `test`.`personal` mapped to number 70
# at 706
#151205 21:08:25 server id 1  end_log_pos 750 CRC32 0x5af605af  Write_rows: table id 70 flags: STMT_END_F

BINLOG '
buJiVhMBAAAANgAAAMICAAAAAEYAAAAAAAEABHRlc3QACHBlcnNvbmFsAAIDDwIeAAJW6Q22
buJiVh4BAAAALAAAAO4CAAAAAEYAAAAAAAEAAgAC//wCAAAAA3Rvba8F9lo=
'/*!*/;
# at 750
#151205 21:08:25 server id 1  end_log_pos 781 CRC32 0x979d473d  Xid = 12
COMMIT/*!*/;

出力されるログはbase64エンコードされている。
オプションをつけて実行する。

–base64-outputでバイナリログのエントリを base-64 エンコードで出力できる。
DECODE-ROWSを指定して、-vオプションもつけることで行イベントをSQLステートメントとしてデコードできる。

詳細はこのあたりを参考

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001 --base64-output=DECODE-ROWS -v

# at 580
#151205 21:08:25 server id 1  end_log_pos 652 CRC32 0x629d7346  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449321070/*!*/;
BEGIN
/*!*/;
# at 652
#151205 21:08:25 server id 1  end_log_pos 706 CRC32 0xb60de956  Table_map: `test`.`personal` mapped to number 70
# at 706
#151205 21:08:25 server id 1  end_log_pos 750 CRC32 0x5af605af  Write_rows: table id 70 flags: STMT_END_F
### INSERT INTO `test`.`personal`
### SET
###   @1=2
###   @2='tom'
# at 750
#151205 21:08:25 server id 1  end_log_pos 781 CRC32 0x979d473d  Xid = 12
COMMIT/*!*/;

updateしてみる

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
# update
UPDATE personal SET name='tommy' WHERE id = 1;

# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001 --base64-output=DECODE-ROWS -v

# at 781
#151206 21:12:11 server id 1  end_log_pos 853 CRC32 0xf1228fc3  Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449368345/*!*/;
BEGIN
/*!*/;
# at 853
#151206 21:12:11 server id 1  end_log_pos 907 CRC32 0xa2ca1af1  Table_map: `test`.`personal` mapped to number 70
# at 907
#151206 21:12:11 server id 1  end_log_pos 963 CRC32 0xdfe4919c  Update_rows: table id 70 flags: STMT_END_F
### UPDATE `test`.`personal`
### WHERE
###   @1=1
###   @2='tom'
### SET
###   @1=1
###   @2='tommy'
# at 963
#151206 21:12:11 server id 1  end_log_pos 994 CRC32 0x81ba30c7  Xid = 16
COMMIT/*!*/;

同じ値でupdateする。

1
2
# update
UPDATE personal SET name='tommy' WHERE id = 1;

更新が発生してないのでログは出力されてない。

Mixed base

最後にMIXEDを試してみる。

1
2
3
4
5
6
7
8
9
10
SET binlog_format = 'MIXED';
Query OK, 0 rows affected (0.01 sec)

SHOW variables LIKE "binlog_format";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | MIXED |
+---------------+-------+
1 row in set (0.00 sec)

データをinsertする。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
# insert
INSERT INTO personal(name) VALUES('tom');

# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001

# at 1198
#151206 21:14:35 server id 1  end_log_pos 1277 CRC32 0xe74bdeed     Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449374917/*!*/;
BEGIN
/*!*/;
# at 1277
# at 1309
#151206 21:14:35 server id 1  end_log_pos 1309 CRC32 0xd5a25039     Intvar
SET INSERT_ID=3/*!*/;
#151206 21:14:35 server id 1  end_log_pos 1423 CRC32 0x2a2b7771     Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449374917/*!*/;
INSERT INTO personal(name) VALUES('tom')
/*!*/;
# at 1423
#151206 21:14:35 server id 1  end_log_pos 1454 CRC32 0x83cb8b10     Xid = 23
COMMIT/*!*/;

STATEMENTと同様で実行したSQLの履歴がログに出力される。
updateする。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
# update
UPDATE personal SET name='tommy' WHERE id = 1;

# show binlog
/*!*/;
# at 1732
#151206 21:16:48 server id 1  end_log_pos 1811 CRC32 0xd0ddade4     Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449375744/*!*/;
BEGIN
/*!*/;
# at 1811
#151206 21:16:48 server id 1  end_log_pos 1930 CRC32 0xb27b4345     Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449375744/*!*/;
update personal set name='tommy' where id = 1
/*!*/;
# at 1930
#151206 21:16:48 server id 1  end_log_pos 1961 CRC32 0x51bab152     Xid = 26
COMMIT/*!*/;

一部の関数を使った場合はROWフォーマットで出力される。
CURRENT_USER() を使って更新してみる。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
# update
UPDATE personal SET name=CURRENT_USER() WHERE id = 1;

# show binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000006
# at 1961
#151206 21:18:04 server id 1  end_log_pos 2033 CRC32 0x62cb65dd     Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449376039/*!*/;
BEGIN
/*!*/;
# at 2033
#151206 21:18:04 server id 1  end_log_pos 2087 CRC32 0x6e57c961     Table_map: `test`.`personal` mapped to number 70
# at 2087
#151206 21:18:04 server id 1  end_log_pos 2150 CRC32 0x6a1d8b78     Update_rows: table id 70 flags: STMT_END_F

BINLOG
J7ljVhMBAAAANgAAACcIAAAAAEYAAAAAAAEABHRlc3QACHBlcnNvbmFsAAIDDwIeAAJhyVdu
J7ljVh8BAAAAPwAAAGYIAAAAAEYAAAAAAAEAAgAC///8AwAAAAV0b21tefwDAAAACnJvb3RAbG9j
YWx4ix1q
'/*!*/;
# at 2150
#151206 21:18:04 server id 1  end_log_pos 2181 CRC32 0x12bf3230     Xid = 29
COMMIT/*!*/;

# decode base64 binlog
mysqlbinlog /usr/local/var/mysql/mysql-bin.000001 --base64-output=DECODE-ROWS -v

# at 1961
#151206 21:18:04 server id 1  end_log_pos 2033 CRC32 0x62cb65dd     Query   thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1449376039/*!*/;
BEGIN
/*!*/;
# at 2033
#151206 21:18:04 server id 1  end_log_pos 2087 CRC32 0x6e57c961     Table_map: `test`.`personal` mapped to number 70
# at 2087
#151206 21:18:04 server id 1  end_log_pos 2150 CRC32 0x6a1d8b78     Update_rows: table id 70 flags: STMT_END_F
### UPDATE `test`.`personal`
### WHERE
###   @1=1
###   @2='tommy'
### SET
###   @1=1
###   @2='root@local'
# at 2150
#151206 21:18:04 server id 1  end_log_pos 2181 CRC32 0x12bf3230     Xid = 29
COMMIT/*!*/;

となりROWベースとなっていることがわかる。

まとめ

STATEMENTは実行したSQL文がログに記載され、エンコードされていないためサイズも小さく、ログも読みづらい。
反面 Non-Deterministic なので、必ずしも同じクエリを実行しても同じ結果が得られるわけでない。
それに対してMIXED、ROWはサイズは大きくなるが、結果が異なってくるということはなく安全である。

デフォルトでMIXEDとかROWとかにした方がいいのじゃないかと思ってたけど、
MySQL 5.7.7からはdefaultがROWになったようだった。

参考にしたページ

4.6.8 mysqlbinlog — バイナリログファイルを処理するためのユーティリティー
MariaDB Binary Log Formats

Comments