查看原文
其他

binlog二进制文件解析

董骐铭 乐得DBA 2019-04-06



本文主要介绍MySQL的binlog二进制文件的解析,目的是更好的了解binlog文件的构成并做相应的二次开发,并帮助对主从复制机制有更多理解。

以下内容基于row的日志格式。操作系统redhat7,MySQL版本5.7.17,开启GTID。


Binlog生成


在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文件构成


对于该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中的解析方式。


FORMAT_DESCRIPTION_EVENT


该部分位于整个文件的头部,每个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末尾都会有这样四个字节,之后也不再赘述。


PREVIOUS_GTIDS_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的编号。


GTID_EVENT/ANONYMOUS_GTID_EVENT


# 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。


QUERY_EVENT



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与建库时一致的,大家可以手动分析下。


TABLE_MAP_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

上查看。


WRITE_ROW_EVENT/DELETE_ROW_EVENT



# 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位仍为校验位。


UPDATE_ROW_EVENT


# 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中完全一致,唯一区别是记录了旧值和新值的两部分内容,此处请自行解析。


XID_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号。


十一
ROTATE_EVENT


# 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

精深数据库神功


    您可能也对以下帖子感兴趣

    文章有问题?点此查看未经处理的缓存