MySQL binlog の読み方を紹介します。検証用 MySQL のバージョンは 5.5 です。

準備

$ sudo service mysqld stop
$ sudo vi /etc/my.cnf

設定例

[mysqld]
user=mysql
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
server-id=000001
log-bin=mysql-bin
binlog_format=2  # row-based logging

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

サービスの起動

$ sudo service mysqld start

binlog に追記されることを確認

mysql> USE mydb;
mysql> CREATE TABLE mytable (cola INT, colb INT);
mysql> INSERT INTO mytable VALUES (1,1),(1,1),(1,1),(1,1),(1,1),(1,1),
       (1,1),(1,1),(1,1),(1,1),(1,1),(1,1),(1,1),(1,1);

mysqlbinlog

$ sudo mysqlbinlog /var/lib/mysql/mysql-bin.000001 --base64-output=DECODE-ROWS -v | less

...
# at 4
#150516  9:44:20 server id 1  end_log_pos 107   Start: binlog v 4, server v 5.5.43-log created 150516  9:44:20 at startup

...
# at 107
#150516  9:52:04 server id 1  end_log_pos 224   Query   thread_id=2     exec_time=0     error_code=0

...
create table mytable (cola int, colb int)

...
# at 224
#150516  9:53:03 server id 1  end_log_pos 305   Query   thread_id=2     exec_time=0     error_code=0

...
### INSERT INTO `mydb`.`mytable`
### SET
###   @1=1
###   @2=1
### INSERT INTO `mydb`.`mytable`
### SET
###   @1=1
###   @2=1
### INSERT INTO `mydb`.`mytable`

バイナリを解析してみる

$ sudo od /var/lib/mysql/mysql-bin.000001 -Ax -tx1z -v
000000 fe 62 69 6e 74 11 57 55 0f 01 00 00 00 67 00 00  >.bint.WU.....g..<
000010 00 6b 00 00 00 01 00 04 00 35 2e 35 2e 34 33 2d  >.k.......5.5.43-<
000020 6c 6f 67 00 00 00 00 00 00 00 00 00 00 00 00 00  >log.............<
000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  >................<
000040 00 00 00 00 00 00 00 00 00 00 00 74 11 57 55 13  >...........t.WU.<
000050 38 0d 00 08 00 12 00 04 04 04 04 12 00 00 54 00  >8.............T.<
000060 04 1a 08 00 00 00 08 08 08 02 00 44 13 57 55 02  >...........D.WU.<
...

マジックナンバー 4 バイト

fe 62 69 6e

"0xfe 0x62 0x69 0x6e" から始まっていることが分かります。後半のみ 3 バイトはアスキーコードで "bin" です。この最初の 4 バイトはマジックナンバーです。公式ページに記載されているようにすべての binlog の開始位置に含まれています。

ヘッダーを読む

マジックナンバーの後は event の繰り返しです。すべての event はヘッダーとデータから構成されます。ヘッダーのフォーマットは MySQL のバージョンに依ります。今回検証用に利用している MySQL は v5.5 ですので v4 フォーマットのヘッダーになります。Event Structure を読みながら解析していきます。

74 11 57 55

timestamp です。mysqlbinlog コマンドの出力結果の "at 4" の event です。ゼロスタートで 4 バイト目から始まっています。今回の環境ではリトルエンディアンになっているようです。55571174 を 10 進数に変換します。

$ echo "obase=10; ibase=16; 55571174" | bc
1431769460

このタイムスタンプを文字列に変換します。

$ date -d @1431769460
2015年  5月 16日 土曜日 18:44:20 JST

これは mysqlbinlog コマンドの出力結果の "150516 9:44:20" と一致します。

0f

type_code です。binlog の最初の event は 0x0f すなわち 15 番です。これは FORMAT_DESCRIPTION_EVENT という event です。event の意味はこちらのページで確認します。binlog を生成した MySQL のバージョンが記載されており、以降の event のログフォーマットを知ることができます。

01 00 00 00

event が発生した server の id です。binlog の最初の event である FORMAT_DESCRIPTION_EVENT は必ず my.cnf で指定した server-id 000001 となります。レプリケーション時には master の server-id が含まれる可能性があることに注意しなければなりません。

67 00 00 00

event_length です。ヘッダーとデータを合わせて 103 バイトあります。本 event は "at 4" ですので次の event は "at 107" であると予想できます。

6b 00 00 00

next_position です。予想通りゼロスタートで 107 バイト目から次の event が開始されることが分かりました。

01 00

flags です。用途は不明です。また extra_headers は binlog の最初の event である FORMAT_DESCRIPTION_EVENT には存在しません。

データを読む

binlog の最初の event である FORMAT_DESCRIPTION_EVENT には variable part はなく fixed part のみ存在します。

04 00

データ部は Event Data for Specific Event Types を参考に解析します。FORMAT_DESCRIPTION_EVENT の最初の fixed part は The binary log format version です。MySQL 5.0 以降は v4 ですので想定通りです。

35 2e 35 2e 34 33 2d...

35 2e 35 2e 34 33 2d
6c 6f 67 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00

アスキーコードに直すと "5.5.43-log" です。The MySQL server's version を表現しています。

74 11 57 55

ヘッダー部にも出力されており冗長ですが再び timestamp です。

13

The header length です。0x13 = 19 ですので Event Structure によると extra_headers は以降の event について Empty であることが分かります。

38 0d 00 08 00 12 00...

38 0d 00 08 00 12 00 04 04 04 04 12 00 00 54 00
04 1a 08 00 00 00 08 08 08 02 00

Variable-sized. An array that indicates the post-header lengths for all event types. There is one byte per event type that the server knows about.

次の event へ

44 13 57 55

timestamp です。

02

type_code は 2 ですので QUERY_EVENT となります。具体的には本ページの最初に発行した CREATE TABLE の binlog event です。この繰り返しを C++ で表現すると mysqlbinlog2 のようになります。アプリ開発時には、こちらで紹介されている MySQL Binary Log Events を利用するとよさそうです。

主要な binlog event

• Event Classes and Types
• Event Meanings
• Event Data for Specific Event Types

FORMAT_DESCRIPTION_EVENT = 15

すべての binlog の最初に発生する event です。binlog で使用される binlog フォーマットのバージョン情報などを知ることができます。

QUERY_EVENT = 2

CREATE, DROP, ALTER, TRUNCATE など DDL (Data Definition Language) や INSERT, UPDATE, DELETE など DML (Data Manipulation Language) の binlog event です。SELECT は DML ですが参照するだけであるため binlog には記載されません。また row-based logging の場合、INSERT, UPDATE, DELETE は QUERY_EVENT= 2 ではなくそれぞれ WRITE_ROWS_EVENT = 23, UPDATE_ROWS_EVENT = 24, DELETE_ROWS_EVENT = 25 となります。上記に加えてトランザクションの BEGIN や COMMIT も QUERY_EVENT に含まれます。

STOP_EVENT = 3

mysqld が停止すると発生します。

ROTATE_EVENT = 4

binlog のログローテーションが実行される直前に発生して binlog の最後に記載されます。FLUSH LOGS が発行されたり binlog のサイズが max_binlog_size を越える場合に発生します。

XID_EVENT = 16

XA-capable storage engine のトランザクション COMMIT 時に発生します。通常 COMMIT は QUERY_EVENT として発生します。

TABLE_MAP_EVENT = 19

row-based logging で発生する event です。あるトランザクション内の WRITE_ROWS_EVENT = 23, UPDATE_ROWS_EVENT = 24, DELETE_ROWS_EVENT = 25 群の直前に発生します。これから操作するテーブルのメタ情報が記載されています。この情報をもとに INSERT, UPDATE, DELETE を行います。Event Data for Specific Event Types に記載されている Packed integer という整数を格納するデータ構造についてはこちらに記載されています。