binlog二进制文件解析
本文主要介绍MySQL的binlog二进制文件的解析,目的是更好的了解binlog文件的构成并做相应的二次开发,并帮助对主从复制机制有更多理解。
以下内容基于row的日志格式。操作系统redhat7,MySQL版本5.7.17,开启GTID。
在MySQL中执行flush logs,并执行以下操作。
mysql> create database abcd;
Query OK, 1 row affected (0.01 sec)
mysql> create table test (a1 int primary key not null auto_increment, a2 double not null, a3 timestamp, a4 datetime, a5 char(10), a6 varchar(4000), a7 text);
Query OK, 0 rows affected (0.21 sec)
mysql> insert into test values(1, 2.222222222, now(), now(), 'abc', 'abcdefghasdasdasd', 'qwetrhyokxocm3479thcms9q25hdr9ker8thcfisdrhoc');
Query OK, 1 row affected (0.08 sec)
mysql> update test set a1=10, a2=3.33333, a3=now(), a4=now(), a5='abcde', a6='a', a7='s' where a1=1;
Query OK, 1 row affected (0.06 sec)
Rows matched:1 Changed: 1 Warnings: 0
mysql> delete from test;
Query OK, 1 row affected (0.04 sec)
mysql> drop table test;
Query OK, 0 rows affected (0.22 sec)
mysql> flush logs;
Query OK, 0 rows affected (0.17 sec)
可以得到文件 mysql-bin.000006
hexdump –C mysql-bin.000006
生成十六进制的解析文件。文件较长,之后会逐层分析。
对于该binlog而言,主要包括以下几种event。
FORMAT_DESCRIPTION_EVENT
GTID_LOG_EVENT/ANONYMOUS_GTID_LOG_EVENT
QUERY_EVENT
TABLE_MAP_EVENT
WRITE_ROW_EVENT/UPDATE_ROW_EVENT/DELETE_ROW_EVENT
XID_EVENT
ROTATE_EVENT
除这些外还有许多其他类型event,但多数不常见或随着binlog版本的升级而弃用。
每个event包括Binlog event header,Post-Header和Body三部分。
其中对于所有event而言,Binlog event header的长度与格式是相同的,之后会在
FORMAT_DESCRIPTION_EVENT部分做统一介绍。
Post-Header对于同类型的event是长度相同的,部分类型的event并没有Post-Header。
Body则为event中的变量部分,主要表示Query event中的变量部分。
下面将详细介绍每一种event在binlog中的解析方式。
该部分位于整个文件的头部,每个binlog文件都必定会有唯一一个该event。
二进制文件内容
解析的binlog
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#180321 18:00:32 server id 1813309 end_log_pos 123 CRC32 0x77f16c93 Start: binlog v 4, server v 5.7.17-log created 180321 18:00:32
BINLOG '
QC2yWg89qxsAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AZNs8Xc=
'/*!*/;
Binlog event header部分:
fe 62 69 6e:文件前四位非Binlog event header部分,而是magic number,在这里指代.bin,代表文件的格式。
后面的Header总长固定为19个字节。
40 2d b2 5a:事件发生的时间戳。应用服务器是X86架构,在存储的时候为小端模式,即低位字节排放在内存的低地址端,也即实际是5a b2 2d 40代表一个数值,解析成时间为2018/3/21 18:00:32。请务必注意,后面的绝大部分数值的表示都将是这样反向的。
0f:type_code,代表该事件的类型,几个重要的事件类型为:
0x02 QUERY_EVENT
0x04 ROTATE_EVENT
0x0f FORMAT_DESCRIPTION_EVENT
0x10 XID_EVENT
0x13 TABLE_MAP_EVENT
0x1d ROWS_QUERY_EVENT
0x1e WRITE_ROWS_EVENTv2
0x1f UPDATE_ROWS_EVENTv2
0x20 DELETE_ROWS_EVENTv2
0x21 GTID_EVENT
0x22 ANONYMOUS_GTID_EVENT
0x23 PREVIOUS_GTIDS_EVENT
3d ab 1b 00:server_id,就是MySQL配置cnf文件中的server_id。这里是00 1b ab 3d,代表1813309。
77 00 00 00:代表整个event的长度,长度为119。
7b 00 00 00:下一个event开始的位置,可以看到与前一个值刚好差4,也就是魔数的长度。
00 00:flags,每个events中flags代表的意义大致相同。在此处 00 00 代表binlog已经关闭, 00 01代表binlog仍开启,具体详见https://dev.mysql.com/doc/internals/en/binlog-event-flag.html。
以上便是所有event的Binlog event header的固定形式,之后便不再解析。
Post-Header 对于每一类型的event都是相同的。
FORMAT_DESCRIPTION_EVENT有Post-Header,并没有Body部分,因为并没有变量。
04 00:binlog的版本,mysql从5.0后日志都是v4版本的。
之后50位代表mysql-server的版本,5.7.17-log。在此处存的是字符串所以不须反过来看。
00 00 00 00:代表create timestamp,官网上解释为seconds since Unix epoch when the binlog was created。
13:代表Binlog event heade的长度,固定长度是19。
之后39位代表了39种类型事件的Post-Header的长度,从0x01开始,与上面所介绍的时间类型是对应的。其中FORMAT_DESCRIPTION_EVENT为0x0f,即长度对应5f。
详细的关系在 https://dev.mysql.com/doc/internals/en/format-description-event.html 上有部分的对应,虽然不全但是可以对应主要的event的Post-Header长度。
可以看到WRITE_ROWS_EVENT、UPDATE_ROWS_EVENT、DELETE_ROWS_EVENT这三种主要event长度都是0x0a,因为他们同属于ROWS_EVENT。
后面四种可以在源码中查到,分别为
TRANSACTION_CONTEXT_HEADER_LEN,VIEW_CHANGE_HEADER_LEN,XA_PREPARE_HEADER_LEN,ROWS_HEADER_LEN_V2。
93 6c f1 77:最后四位为循环冗余校验码,与解析出的CRC32 0x77f16c93是一致的。注意,每一个event末尾都会有这样四个字节,之后也不再赘述。
# at 123
#180321 18:00:32 server id 1813309 end_log_pos 194 CRC32 0xfeb5737a Previous-GTIDs
# c5f7f863-1b95-11e8-9e24-0024e8629bab:1-4
Event type是23,紧接着FORMAT_DESCRIPTION_EVENT。
这个也是单个binlog文件中唯一的event,无论是否开关GTID都存在的。主要用来表示上一个binlog的最后一个GTID的位置。
Binlog event header中与前面解析唯一不同之处为flags的值是80,代表LOG_EVENT_IGNORABLE_F,在8.0官网写着是代表这事件可以被忽略 (emm..
该event只有Body变量部分,没有Post-Header,这个的解析官网和源码上给的都不清晰,只能暂且做简单的判断。
c5 f7 f8 63 1b 95 11 e8 9e 24 00 24 e8 62 9b ab:中间十六字节代表server_uuid。
05 00 00 00 00 00 00 00:最后8位代表最新的GTID的编号。
# at 194
#180321 18:00:45 server id 1813309 end_log_pos 259 CRC32 0x606aa948 GTID last_committed=0 sequence_number=1
SET @@SESSION.GTID_NEXT= 'c5f7f863-1b95-11e8-9e24-0024e8629bab:5'/*!*/;
event type是21,即GTID_EVENT。如果没有开启GTID模式,事件类型会是ANONYMOUS_GTID_EVENT,这两个都属于Gtid_log_event。
01:commit flag,代表事务提交情况。
c5 f7 f8 63 1b 95 11 e8 9e 24 00 24 e8 62 9b ab:server_uuid
05 00 00 00 00 00 00 00:该GTID号,与上文相同。
02:TS_TYPE,官网解释 TS_TYPE is from {G_COMMIT_TS2} singleton set of values。
00 00 00 00 00 00 00 00:代表last_committed号 0
01 00 00 00 00 00 00 00:代表sequence_number号 1。
每一个Query事务前都会有这样的一个GTID_EVENT,如果未开启则是ANONYMOUS_GTID_EVENT。
其中ANONYMOUS_GTID_EVENT只有last_committed和sequence_number号,因为没有GTID号生成因此其他位皆为0。
SET TIMESTAMP=1521626445/*!*/;
SET @@session.pseudo_thread_id=95906/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1437073442/*!*/;
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/*!*/;
create database abcd
/*!*/;
# at 353
#180321 18:04:24 server id 1813309 end_log_pos 418 CRC32 0x8f20b94b GTID last_committed=1 sequence_number=2
在row格式的binlog中,所有的建库建表操作都是QUERY_EVENT。此处取出较短的建库操作做分析,建表操作与建库的binlog格式是完全相同的。
Post-Header的长度为0x0d。
00 01 76 a2:slave_proxy_id,代指一个用于临时表的进程号,为了避免创建临时表时重复。
00 00 00 00:表示语句执行时间,单位为秒。
04 :代表当前数据库名字的长度,在这里为abcd。
00 00 :两位错误码,若非0则代表有误,如果从库在复制时收到错误码将停止复制进程。
00 21 :v4新特性,为status_vars的长度,这个之后会有介绍。
Body的长度根据DDL语句的长度而定。
注意,此处的数据解析并不是连续不断的形式,而是类似于key-value的形式,即一个单字节键名,对应数个字节的值。
00 00 00 00 00:键是00 代表Q_FLAGS2_CODE,以下是对应关系详情
0x00004000 OPTION_AUTO_IS_NULL SQL_AUTO_IS_NULL
0x00080000 OPTION_NOT_AUTOCOMMIT FOREIGN_KEY_CHECKS
0x04000000 OPTION_NO_FOREIGN_KEY_CHECKS UNIQUE_CHECKS
0x08000000 OPTION_RELAXED_UNIQUE_CHECKS AUTOCOMMIT
每一项都属于叠加的形式,即0x00084000 代表数据库有前两项属性,之后的情况类似。
此处值为00 00 00 00,即不满足上述条件。
01 22 00 a8 55 00 00 00 00:键是01 代表Q_SQL_MODE_CODE,值为 00 00 00 00 55 a8 00 22。具体的转换内容详见https://dev.mysql.com/doc/internals/en/query-event.html#q-flags2-code。在这里代表sql_mode的配置,跟上面一样都属于叠加的模式。
通过文档可以解析出sql_mode为
PIPES_AS_CONCAT,ONLY_FULL_GROUP_BY,NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION。
06 03 73 74 64:键是06 代表Q_CATALOG_NZ_CODE,值为 03 73 74 64
03代表字符串长度,73 74 64指代std字符串。
04 2d 00 2d 00 2d 00:键是04 代表Q_CHARSET_CODE,后面为三个双字节数字,都为0x002d。分别是指@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45。
0c 01 61 62 63 64 00:键是0x0c 代表Q_UPDATED_DB_NAMES,后面跟为单字节的01,代表存储访问数据从库的总数,测试环境中仅有一个从库。之后跟的便是对应的数据库的名称,61 62 63 64对应abcd库名,其中字符串需要以00来结尾字符串。
建表的QUERY_EVENT与建库时一致的,大家可以手动分析下。
SET TIMESTAMP=1521626714/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
BEGIN
/*!*/;
# at 782
#180321 18:05:14 server id 1813309 end_log_pos 843 CRC32 0x98b87aed Table_map: `abcd`.`test` mapped to number 224
每个DML事务之前,都会有一个TABLE_MAP_EVENT,记录操作对应的表的信息。
Post-Header的长度为0x08。
e0 00 00 00 00 00:代表库的ID 224。
01 00 :保留位数,Reserved for future use。
Body部分:
04:库名的长度,之后是库名的字符串61 62 63 64 00 abcd,与上文相同。
04:表名的长度,和对应的表名74 65 73 74 00 test。
07:代表字段的个数,我们建表时设立了7种不同类型的字段。
可以看出,binlog是完全不记录表的字段名称的,只记录对应的编号和类型。
让我们重新看一下建表的内容。
create table test (a1 int primary key not null auto_increment, a2 double not null, a3 timestamp, a4 datetime, a5 char(10), a6 varchar(4000), a7 text);
03 05 11 12 fe 0f fc 08 08 00 00 fe 28 80 3e 02 78
其中每个字节都有对应的含义。
03代表MYSQL_TYPE_LONG。
05代表MYSQL_TYPE_DOUBLE,后面会跟一位metadata。
11代表MYSQL_TYPE_TIME,这个官网写后面没有metadata,但是其实是有一个00站位的,而且跟是否有默认值无关。
12代表MYSQL_TYPE_DATETIME,跟MYSQL_TYPE_TIME情况相同。
Fe代表MYSQL_TYPE_STRING,后面会跟两位metadata
0f代表MYSQL_TYPE_VARCHAR,后面会跟两位metadata
Fc代表MYSQL_TYPE_BLOB,后面会跟一位metadata
之后的08代表metadata length:08 00 00 fe 28 80 3e 02
首先08对应的MYSQL_TYPE_DOUBLE的metadata,代表sizeof(double),也就是8
之后00 00就跟上文说的一样,是MYSQL_TYPE_TIME和MYSQL_TYPE_DATETIME的metadata。
fe 28:在之后的insert语句的binlog中,可以看到有@5='abc' /* STRING(40) meta=65064 nullable=1 is_null=0 */的内容,其中的meta值便是0xfe28。
80 3e: 与第六列中@6='abcdefghasdasdasd' /* VARSTRING(16000) meta=16000 nullable=1 is_null=0 */中的meta值一致。
02:与第七列中@7='qwetrhyokxocm3479thcms9q25hdr9ker8thcfisdrhoc' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */中的meta值一致。
78这一字节比较特殊,我们需要把它拆为01111000,后七位分别对应表的七个字段,其中1代表非空,0代表可为空。如果表的字段个数超过8的话就会多字节来表示。
详细的对应关系可以到
https://dev.mysql.com/doc/dev/mysql-server/8.0.0/classbinary__log_1_1Table__map__event.html
上查看。
# at 843
#180321 18:05:14 server id 1813309 end_log_pos 970 CRC32 0x6c6819d3 Write_rows: table id 224 flags: STMT_END_F
MYSQL_TYPE_LONG
BINLOG '
Wi6yWhM9qxsAPQAAAEsDAAAAAOAAAAAAAAEABGFiY2QABHRlc3QABwMFERL+D/wICAAA/iiAPgJ4
7Xq4mA==
Wi6yWh49qxsAfwAAAMoDAAAAAOAAAAAAAAEAAgAH/4ABAAAAwnm/cRzHAUBasi5amZ9rIU4DYWJj
EQBhYmNkZWZnaGFzZGFzZGFzZC0AcXdldHJoeW9reG9jbTM0Nzl0aGNtczlxMjVoZHI5a2VyOHRo
Y2Zpc2RyaG9j0xlobA==
'/*!*/;
### INSERT INTO `abcd`.`test`
### SET
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=2.2222222220000000803 /* DOUBLE meta=8 nullable=0 is_null=0 */
### @3=1521626714 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
### @4='2018-03-21 18:05:14' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @5='abc' /* STRING(40) meta=65064 nullable=1 is_null=0 */
### @6='abcdefghasdasdasd' /* VARSTRING(16000) meta=16000 nullable=1 is_null=0 */
### @7='qwetrhyokxocm3479thcms9q25hdr9ker8thcfisdrhoc' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
在这里将插入和删除event放在一起说明,主要是两者除了Header中event type不同外,其余的内容完全一致(WRITE_ROW_EVENTv2的event type为0x1e,DELETE_ROW_EVENT v2的event type为0x20)。也就是说,只要替换下事件类型,就可以从insert变为delete。
这类event MySQL 5.1.0 至5.1.15是v0版本,MySQL 5.1.15 至5.6.x为v1版本,MySQL 5.6.x之后为v2版本。
Post-Header的长度为0x0a。
e0 00 00 00 00 00 01 00 02 00
e0 00 00 00 00 00:table id 224。
01 00:flags,代表end of statement。
0x0001 end of statement
0x0002 no foreign key checks
0x0004 no unique key checks
0x0008 row has a columns
02 00:extra_data_len,需要大于等于2,官网上写为extra row data的长度。
Body部分:
07:表有7个字段。
ff:官网上解释为m_cols。
80:1000000,跟TABLE_MAP_EVENT上面一致,只看后七位,表示哪些字段有写入null的情况。其中0代表写入,1代表null。该字段的长度为INT((N + 7) / 8) bytes。N代表列数。
执行的语句是insert into test
values(1,2.222222222,now(),now(),'abc','abcdefghasdasdasd','qwetrhyokxocm3479thcms9q25hdr9ker8thcfisdrhoc');
01 00 00 00:首列是int,插入的值为1。
c2 79 bf 71 1c c7 01 40:第二列是double,上面已经看到sizeof(double)为8。
5a b2 2e 5a :第三列值为1521626714,代表写入的now()的时间戳。
99 9f 6b 21 4e:此处代表'2018-03-21 18:05:14',是datetime类型字段。
03 61 62 63:第五列,首先03代表位数,之后便是abc字符串。
11 00 61 62 63 64 65 66 67 68 61 73 64 61 73 64 61 73 64:第六列,首先0x11代表位数17位。之后出现了00,此处的00代表上一个字符串结束的标识,即将开始17位新的字符串。之后表示的便是abcdefghasdasdasd。
第七列的字符串较长,就不再赘述。
最后4位仍为校验位。
# at 1207
#180321 18:06:16 server id 1813309 end_log_pos 1369 CRC32 0x3cbdcd8d Update_rows: table id 224 flags: STMT_END_F
BINLOG '
mC6yWhM9qxsAPQAAALcEAAAAAOAAAAAAAAEABGFiY2QABHRlc3QABwMFERL+D/wICAAA/iiAPgJ4
5WTVNA==
mC6yWh89qxsAogAAAFkFAAAAAOAAAAAAAAEAAgAH//+AAQAAAMJ5v3EcxwFAWrIuWpmfayFOA2Fi
YxEAYWJjZGVmZ2hhc2Rhc2Rhc2QtAHF3ZXRyaHlva3hvY20zNDc5dGhjbXM5cTI1aGRyOWtlcjh0
aGNmaXNkcmhvY4AKAAAAmDRG66iqCkBasi6YmZ9rIZAFYWJjZGUBAGEBAHONzb08
'/*!*/;
### UPDATE `abcd`.`test`
### WHERE
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=2.2222222220000000803 /* DOUBLE meta=8 nullable=0 is_null=0 */
### @3=1521626714 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
### @4='2018-03-21 18:05:14' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @5='abc' /* STRING(40) meta=65064 nullable=1 is_null=0 */
### @6='abcdefghasdasdasd' /* VARSTRING(16000) meta=16000 nullable=1 is_null=0 */
### @7='qwetrhyokxocm3479thcms9q25hdr9ker8thcfisdrhoc' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
### @2=3.3333300000000001262 /* DOUBLE meta=8 nullable=0 is_null=0 */
### @3=1521626776 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
### @4='2018-03-21 18:06:16' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @5='abcde' /* STRING(40) meta=65064 nullable=1 is_null=0 */
### @6='a' /* VARSTRING(16000) meta=16000 nullable=1 is_null=0 */
### @7='s' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
执行的sql为update test set a1=10,a2=3.33333,a3=now(),a4=now(),a5='abcde',a6='a',a7='s' where a1=1
在解析的binlog文件中可以看出,binlog记载的是一条记录的完整的变化情况,即从前量变为后量的过程,并没有记录执行语句的条件等信息。
Fixed data部分与上面所述完全一致
Variable data部分:
第二位ff后又接了一位ff,与上面一致,为前量后量的m_cols。
之后的解析便与WRITE_ROW_EVENT中完全一致,唯一区别是记录了旧值和新值的两部分内容,此处请自行解析。
# at 970
#180321 18:05:14 server id 1813309 end_log_pos 1001 CRC32 0xb73f8e76 Xid = 8096890
COMMIT/*!*/;
Xid event比较短,主要是事务提交的时候回在最后生成一个xid号,有这个便代表事务已经成功提交了。
只有Body且一共就八位。
7a 8c 7b 00 00 00 00 00,为8096890,代表xid号。
# at 1880
#180321 18:06:37 server id 1813309 end_log_pos 1927 CRC32 0xe42f7923 Rotate to mysql-bin.000007 pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
Binlog结束时的事件,与FORMAT_DESCRIPTION_EVENT一样仅有一个。
Post-Header的长度为8位:
04 00 00 00 00 00 00 00:代表第一个事件开始的位置,为4.
Body:
6d 79 73 71 6c 2d 62 69 6e 2e 30 30 30 30 30 37 代表mysql-bin.000007,为下个binlog的文件名。
至此全部事件解析结束。
在之后的文章中,我们会逐渐介绍binlog主从复制机制和相关的二次开发工作。
点击下方阅读原文,加入我们。
网易乐得DBA组负责网易乐得电商、网易邮箱、网易技术部数据库日常运维
负责数据库私有云平台的开发和维护
负责数据库及数据库中间件的开发和测试等
分享最前沿实用数据库干货
关注网易乐得DBA
精深数据库神功