MySQL Binlog解析 | 忙忙碌碌网

2022年10月3日10:13:42

概述

MySQL的安装可以参考：Linux(CentOS)中常用软件安装，使用及异常——MySQL, VmTools

MySQL关于Binlog的官方文档：The Binary Log

什么是 Binlog

MySQL Server 有四种类型的日志——Error Log、General Query Log、Binary Log 和 Slow Query Log。

第一个是错误日志，记录 mysqld 的一些错误。第二个是一般查询日志，记录 mysqld 正在做的事情，比如客户端的连接和断开、来自客户端每条 Sql Statement 记录信息；如果你想准确知道客户端到底传了什么瞎 [哔哔] 玩意儿给服务端，这个日志就非常管用了，不过它非常影响性能。第四个是慢查询日志，记录一些查询比较慢的 SQL 语句——这种日志非常常用，主要是给开发者调优用的。

剩下的第三种就是 Binlog 了，包含了一些事件，这些事件描述了数据库的改动，如建表、数据改动等，也包括一些潜在改动，比如 DELETE FROM ran WHERE bing = luan，然而一条数据都没被删掉的这种情况。除非使用 Row-based logging，否则会包含所有改动数据的 SQL Statement。

那么 Binlog 就有了两个重要的用途——复制和恢复。比如主从表的复制，和备份恢复什么的。

显然，我们执行SELECT等不设计数据变更的语句是不会记录Binlog的，而涉及到数据更新则会记录。要注意的是，对支持事务的引擎如InnoDB而言，必须要提交了事务才会记录Binlog。Binlog是在事务最终commit前写入的，binlog什么时候刷新到磁盘跟参数sync_binlog相关。如果设置为0，则表示MySQL不控制binlog的刷新，由文件系统去控制它缓存的刷新，而如果设置为不为0的值则表示每sync_binlog次事务，MySQL调用文件系统的刷新操作刷新binlog到磁盘中。设为1是最安全的，在系统故障时最多丢失一个事务的更新，但是会对性能有所影响，一般情况下会设置为100或者0，牺牲一定的一致性来获取更好的性能。

开启和停用Binlog

通过配置/etc/my.cnf配置文件的log-bin选项：

[mysqld]log-bin=mysql-bin

这个需要重启MySQL服务。
可以使用SET SQL_LOG_BIN=0命令停止使用日志文件，然后可以通过SET SQL_LOG_BIN=1命令来启用。

Binlog的删除

mysql> show variables like'expire_log_days';
mysql>setglobal expire_log_days=3;//过期删除
mysql> reset master;//删除master的binlog
mysql> reset slave;//删除slave的中继日志
mysql> purge master logs before'2016-10-20 16:25:00';//删除指定日期前的日志索引中binlog日志文件
mysql> purge master logsto'binlog.000002';//删除指定日志文件

除了以上方法之外，也可以采用操作系统的本地命令删除文件。

Binlog文件的扩展

当遇到以下3种情况时会重新生成一个新的日志文件，文件序号递增：

MySQL服务器停止或重启时，MySQL会在重启时生成一个新的日志文件；
使用flush logs命令；
当binlog文件大小超过max_binlog_size系统变量配置的上限时；

binlog文件的最大值和默认值是1GB，该设置并不能严格控制binlog的大小，尤其是binlog比较靠近最大值而又遇到一个比较大事务时，为了保证事务的完整性，不可能做切换日志的动作，只能将该事务的所有SQL都记录到当前日志，直到事务结束。

Binlog的日志格式

binlog有三种格式：Statement, Row和Mixed.

基于SQL语句的复制（statement-based replication, SBR）
基于行的复制（row-based replication, RBR）
混合模式复制（mixed-based replication, MBR）

Statement

每一条会修改数据的sql都会记录在binlog中。

优点：不需要记录每一行的变化，减少了binlog日志量，节约了IO, 提高了性能。

缺点：由于记录的只是执行语句，为了这些语句能在slave上正确运行，因此还必须记录每条语句在执行的时候的一些相关信息，以保证所有语句能在slave得到和在master端执行的时候相同的结果。另外mysql的复制，像一些特定函数的功能，slave可与master上要保持一致会有很多相关问题。

相比row能节约多少性能与日志量，这个取决于应用的SQL情况，正常同一条记录修改或者插入row格式所产生的日志量还小鱼statement产生的日志量，但是考虑到如果带条件的update操作，以及整表删除，alter表等操作，row格式会产生大量日志，因此在考虑是否使用row格式日志时应该根据应用的实际情况，其所产生的日志量会增加多少，以及带来的IO性能问题。

Row

5.1.5版本的MySQL才开始支持row level的复制,它不记录sql语句上下文相关信息，仅保存哪条记录被修改。

优点： binlog中可以不记录执行的sql语句的上下文相关的信息，仅需要记录那一条记录被修改成什么了。所以row的日志内容会非常清楚的记录下每一行数据修改的细节。而且不会出现某些特定情况下的存储过程，或function，以及trigger的调用和触发无法被正确复制的问题.

缺点:所有的执行的语句当记录到日志中的时候，都将以每行记录的修改来记录，这样可能会产生大量的日志内容。

新版本的MySQL中对row level模式也被做了优化，并不是所有的修改都会以row level来记录，像遇到表结构变更的时候就会以statement模式来记录，如果sql语句确实就是update或者delete等修改数据的语句，那么还是会记录所有行的变更。

Mixed

从5.1.8版本开始，MySQL提供了Mixed格式，实际上就是Statement与Row的结合。
在Mixed模式下，一般的语句修改使用statment格式保存binlog，如一些函数，statement无法完成主从复制的操作，则采用row格式保存binlog，MySQL会根据执行的每一条具体的sql语句来区分对待记录的日志形式，也就是在Statement和Row之间选择一种。

详述

查看Binlog文件

查看当前服务器使用的二进制文件及大小：

mysql> show binary logs;
+------------------+-----------+| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       126 |
| mysql-bin.000002 |       126 |
| mysql-bin.000003 |      6819 |
| mysql-bin.000004 |      2749 || mysql-bin.000005 |      1475 |
+------------------+-----------+

显示主服务器使用的二进制文件及大小：

mysql> show master logs;
+------------------+-----------+| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       126 |
| mysql-bin.000002 |       126 |
| mysql-bin.000003 |      6819 |
| mysql-bin.000004 |      2749 || mysql-bin.000005 |      1475 |
+------------------+-----------+

显示当前使用的二进制文件及所处位置：

mysql> show master status;
+------------------+----------+--------------+------------------+| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+| mysql-bin.000005 |     1475 |              |                  |
+------------------+----------+--------------+------------------+

binlog_do_db：此参数表示只记录制定数据库的二进制日志
binlog_ignore_db：此参数标示不记录指定的数据库的二进制日志

需要查看某个具体binlog文件的内容时，以“mysql-bin.000005”为例。
在MySQL客户端输入：show binlog events in “mysql-bin.000005”;
效果如下所示：

mysql> show binlog eventsin'mysql-bin.000005';+------------------+-----+-------------+-----------+-------------+---------------------------------------+| Log_name| Pos| Event_type| Server_id| End_log_pos| Info|+------------------+-----+-------------+-----------+-------------+---------------------------------------+| mysql-bin.000005|4| Format_desc|2|107| Server ver:5.5.51-log, Binlog ver:4|| mysql-bin.000005|107| Query|2|181| BEGIN|| mysql-bin.000005|181| Table_map|2|239| table_id:44 (canal_test.company)|| mysql-bin.000005|239| Write_rows|2|287| table_id:44 flags: STMT_END_F|| mysql-bin.000005|287| Xid|2|314| COMMIT/* xid=23915 */|| mysql-bin.000005|314| Query|2|388| BEGIN|| mysql-bin.000005|388| Table_map|2|449| table_id:35 (canal_test.person)|| mysql-bin.000005|449| Update_rows|2|526| table_id:35 flags: STMT_END_F|| mysql-bin.000005|526| Xid|2|553| COMMIT/* xid=26960 */|| mysql-bin.000005|553| Query|2|627| BEGIN|| mysql-bin.000005|627| Table_map|2|688| table_id:35 (canal_test.person)|| mysql-bin.000005|688| Write_rows|2|741| table_id:35 flags: STMT_END_F|| mysql-bin.000005|741| Xid|2|768| COMMIT/* xid=26961 */|| mysql-bin.000005|768| Query|2|842| BEGIN|| mysql-bin.000005|842| Table_map|2|903| table_id:35 (canal_test.person)|| mysql-bin.000005|903| Delete_rows|2|956| table_id:35 flags: STMT_END_F|| mysql-bin.000005|956| Xid|2|983| COMMIT/* xid=26964 */|+------------------+-----+-------------+-----------+-------------+---------------------------------------+17rowsinset (0.00 sec)

或者使用mysqlbinlog命令，在shell终端输入（假设当前目录为 ../mysql/data）: ../bin/mysqlbinlog mysql-bin.000005

[root@zhuzhonghua1-c6uu8 data]# pwd
/usr/local/mysql/data
[root@zhuzhonghua1-c6uu8 data]# ../bin/mysqlbinlog mysql-bin.000005/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;/*!40019 SET @@session.max_insert_delayed_threads=0*/;/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER/*!*/;# at 4#161020 11:07:29 server id 2  end_log_pos 107   Start: binlog v 4, server v 5.5.51-log created 161020 11:07:29# Warning: this binlog is either in use or was not closed properly.
BINLOG'
8TQIWA8CAAAAZwAAAGsAAAABAAQANS41LjUxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;# at 107#161020 11:08:50 server id 2  end_log_pos 181   Query   thread_id=162   exec_time=1 error_code=0
SET TIMESTAMP=1476932930/*!*/;
SET @@session.pseudo_thread_id=162/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN/*!*/;# at 181# at 239#161020 11:08:50 server id 2  end_log_pos 239   Table_map: `canal_test`.`company` mapped to number 44#161020 11:08:50 server id 2  end_log_pos 287   Write_rows: table id 44 flags: STMT_END_F

BINLOG'
QjUIWBMCAAAAOgAAAO8AAAAAACwAAAAAAAEACmNhbmFsX3Rlc3QAB2NvbXBhbnkAAwMPDwQsASwB
Bg==
QjUIWBcCAAAAMAAAAB8BAAAAACwAAAAAAAEAA//4AgAAAAIAZHAIAHNoYW5naGFp
'/*!*/;# at 287#161020 11:08:50 server id 2  end_log_pos 314   Xid = 23915
COMMIT/*!*/;# at 314#161020 12:03:50 server id 2  end_log_pos 388   Query   thread_id=162   exec_time=0 error_code=0
SET TIMESTAMP=1476936230/*!*/;
BEGIN/*!*/;# at 388# at 449#161020 12:03:50 server id 2  end_log_pos 449   Table_map: `canal_test`.`person` mapped to number 35#161020 12:03:50 server id 2  end_log_pos 526   Update_rows: table id 35 flags: STMT_END_F

BINLOG'
JkIIWBMCAAAAPQAAAMEBAAAAACMAAAAAAAEACmNhbmFsX3Rlc3QABnBlcnNvbgAFAw8D/g8GLAH+
AywBHg==
JkIIWBgCAAAATQAAAA4CAAAAACMAAAAAAAEABf//4AEAAAADAHp6aAIAAAABbQQAaGVyZeABAAAA
AwB6emgCAAAAAW0HAG5hbmppbmc=
'/*!*/;# at 526#161020 12:03:50 server id 2  end_log_pos 553   Xid = 26960
COMMIT/*!*/;# at 553#161020 12:05:56 server id 2  end_log_pos 627   Query   thread_id=162   exec_time=0 error_code=0
SET TIMESTAMP=1476936356/*!*/;
BEGIN/*!*/;# at 627# at 688#161020 12:05:56 server id 2  end_log_pos 688   Table_map: `canal_test`.`person` mapped to number 35#161020 12:05:56 server id 2  end_log_pos 741   Write_rows: table id 35 flags: STMT_END_F

BINLOG'
pEIIWBMCAAAAPQAAALACAAAAACMAAAAAAAEACmNhbmFsX3Rlc3QABnBlcnNvbgAFAw8D/g8GLAH+
AywBHg==
pEIIWBcCAAAANQAAAOUCAAAAACMAAAAAAAEABf/gBAAAAAQAenpoNBYAAAABbQUAd2hlcmU=
'/*!*/;# at 741#161020 12:05:56 server id 2  end_log_pos 768   Xid = 26961
COMMIT/*!*/;# at 768#161020 12:06:34 server id 2  end_log_pos 842   Query   thread_id=162   exec_time=0 error_code=0
SET TIMESTAMP=1476936394/*!*/;
BEGIN/*!*/;# at 842# at 903#161020 12:06:34 server id 2  end_log_pos 903   Table_map: `canal_test`.`person` mapped to number 35#161020 12:06:34 server id 2  end_log_pos 956   Delete_rows: table id 35 flags: STMT_END_F

BINLOG'
ykIIWBMCAAAAPQAAAIcDAAAAACMAAAAAAAEACmNhbmFsX3Rlc3QABnBlcnNvbgAFAw8D/g8GLAH+
AywBHg==
ykIIWBkCAAAANQAAALwDAAAAACMAAAAAAAEABf/gBAAAAAQAenpoNBYAAAABbQUAd2hlcmU=
'/*!*/;# at 956#161020 12:06:34 server id 2  end_log_pos 983   Xid = 26964
COMMIT/*!*/;
DELIMITER ;# End of log file
ROLLBACK/* added by mysqlbinlog */;/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

截取上面的一段进行分析：

# at 314#161020 12:03:50 server id 2  end_log_pos 388   Query   thread_id=162   exec_time=0 error_code=0
SET TIMESTAMP=1476936230/*!*/;
BEGIN/*!*/;

上面输出包括如下要素：

position: 位于文件中的位置，即第一行的（# at 314）,说明该事件记录从文件第314个字节开始
timestamp: 事件发生的时间戳，即第二行的（#161020 11:07:29）
exec_time: 事件执行的花费时间
error_code: 错误码
server id: 服务器标识（2）
thread_id: 代理线程id （thread_id=162）
type:事件类型Query(参考下一章节)

使用mysqlbinlog命令还可以进行数据库恢复，使用日志进行恢复时，需要依次进行，即最早生成的日志文件要最先恢复：

mysqlbinlog mysql-bin.000001| mysql-uroot-proot
mysqlbinlog mysql-bin.000002| mysql-uroot-proot.....

Binlog事件

Binlog事件类型

binlog事件类型一共有三个版本：

v1: Used in MySQL 3.23
v3: Used in MySQL 4.0.2 though 4.1
v4: Used in MySQL 5.0 and up

v2出现了很短的时间，并且已经不被支持

现在所使用的MySQL一般都是5.5起了，所以下面陈述的都是v4版的binlog事件类型。

binlog的事件类型一共有以下几种：

enumLog_event_type { 
  UNKNOWN_EVENT=0, 
  START_EVENT_V3=1, 
  QUERY_EVENT=2, 
  STOP_EVENT=3, 
  ROTATE_EVENT=4, 
  INTVAR_EVENT=5, 
  LOAD_EVENT=6, 
  SLAVE_EVENT=7, 
  CREATE_FILE_EVENT=8, 
  APPEND_BLOCK_EVENT=9, 
  EXEC_LOAD_EVENT=10, 
  DELETE_FILE_EVENT=11, 
  NEW_LOAD_EVENT=12, 
  RAND_EVENT=13, 
  USER_VAR_EVENT=14, 
  FORMAT_DESCRIPTION_EVENT=15, 
  XID_EVENT=16, 
  BEGIN_LOAD_QUERY_EVENT=17, 
  EXECUTE_LOAD_QUERY_EVENT=18, 
  TABLE_MAP_EVENT =19, 
  PRE_GA_WRITE_ROWS_EVENT =20, 
  PRE_GA_UPDATE_ROWS_EVENT =21, 
  PRE_GA_DELETE_ROWS_EVENT =22, 
  WRITE_ROWS_EVENT =23, 
  UPDATE_ROWS_EVENT =24, 
  DELETE_ROWS_EVENT =25, 
  INCIDENT_EVENT=26, 
  HEARTBEAT_LOG_EVENT=27, 
  IGNORABLE_LOG_EVENT=28,
  ROWS_QUERY_LOG_EVENT=29,
  WRITE_ROWS_EVENT_V2 =30,
  UPDATE_ROWS_EVENT_V2 =31,
  DELETE_ROWS_EVENT_V2 =32,
  GTID_LOG_EVENT=33,
  ANONYMOUS_GTID_LOG_EVENT=34,
  PREVIOUS_GTIDS_LOG_EVENT=35, 
  ENUM_END_EVENT/* end marker */ 
};

20-22三个类型现在已经被飞起，这三个类型只出现在MySQL的5.1.5-5.1.7版本中。现在（从5.1.7版本开始）使用的WRITE, UPDATE, DELETE三个事件类型分别采用23，24，25。

事件类型简述

QUERY_EVENT

记录一条query语句，在基于语句的复制和基于行的复制都会有。

ROTATE_EVENT

二进制日志更换一个新文件，可能因为文件大小达到限制，或者是mysql重启，亦或者是调用了flush logs命令。

XID_EVENT

Commit事件

WRITE_ROWS_EVENT, UPDATE_ROWS_EVENT, DELETE_ROWS_EVENT

统称为ROW EVENT, 只有在基于row的复制方式下才会产生。

WRITE_ROWS_EVENT：包含了要插入的数据
UPDATE_ROWS_EVENT：包含了修改前的值，也包含了修改后的值
DELETE_ROWS_EVENT：包含了需要删除行前的值

TABLE_MAP_EVENT

ROW EVENT之前产生，为的是对ROW EVENT解析提供依据。

FORMAT_DESCRIPTION_EVENT

MySQL根据其定义来解析其他事件

INTVAR_EVET

在statement时使用到，用于自增类型auto_increment.

STOP_EVENT

MySQL停止时，在文件尾加入STOP_EVENT

更多事件类型可以参考MySQL官方文档：http://dev.mysql.com/doc/internals/en/event-meanings.html

事件类型分析

每个event都有一个19个字节的Binlog Event Header（如下图）, 包括四个字节的timestamep, 一个字节的Binlog Event type, 4个字节的server_id（该id表明binlog的源server是哪个，用来在循环复制中国龙event），四个字节的event包大小，四个字节的下一个event起始偏移，两个字节的Binlog Event Flag. extra_headers目前的event中没有涉及到，预留用。

V4 event structure:

MySQL Binlog解析

一个新的binlog文件都是以FORMAT_DESCRIPTION_EVENT开始的（v4版）。这里就以FORMAT_DESCRIPTION_EVENT为例来解析下(mysql-bin.000005)。通过hexdump -C mysql-bin.000005来查看二进制文件。（下面只列出部分内容）

[root@zhuzhonghua1-c6uu8 data]# hexdump -C mysql-bin.00000500000000  fe62696e f13408580f02000000670000|.bin.4.X.....g..|00000010006b00000001000400352e352e35312d|.k.......5.5.51-|000000206c6f6700000000000000000000000000|log.............|0000003000000000000000000000000000000000|................|0000004000000000000000000000000000000013|................|00000050380d0008001200040404041200005400|8.............T.|00000060041a0800000008080802004235085802|...........B5.X.|00000070020000004a000000  b50000000800 a200|....J...........|000000800000010000000a00001a000000000000|................|0000009001000000000000000006037374640421|...........std.!|

按照官方文档中的说明来看下FORMAT_DESCRIPTION_EVENT格式:

v4 format description event

MySQL Binlog解析

binlog是小端字节序的。binlog前4个字节是魔数：0xFE 0x62 0x69 0x6E. 接着是一个FORMAT_DESCRIPTION_EVENT，先看下19个字节的event header. f1 34 08 58即0x580834f1是指时间戳，占4个字节；第5个字节0x0f是type_code即event type（FORMAT_DESCRIPTION_EVENT=15）；接着4个字节02 00 00 00 即0x00000002是server_id；再接着4个字节67 00 00 00是event_length=0x00000067=103;然后4个字节6b 00 00 00是下一个next_position=0x0000006b=107；接着两个字节01 00是flag=0x0001=1,1为LOG_EVENT_BINLOG_IN_USE_F,标识binlog还没有关闭，binlog关闭后，flag会被设置为0。这样4+1+4+4+4+2=19个字节。

event data部分分为fixed data和variable data两部分，其中fixed data是event的固定长度和格式的数据，variable data则是长度变化的数据，比如FORMAT_DESCRIPTION_EVENT的fix data长度是0x54=84字节。下面看下这84=2+50+4+1+27个字节的分配：开始的2个字节0x0004是binlog的版本号；接着的50个字节为mysql-server版本5.5.51-log；接下来4个字节是binlog创建时间，这里是0；然后1个字节是0x13是指之后所有event的公共长度，这里都是19；接着27个字节中每个字节为mysql已知的event（共27个）的fixed data的长度；可以发现FORMAT_DESCRIPTION_EVENT自身的variable data部分为空。

参考资料:
1.Linux(CentOS)中常用软件安装，使用及异常——MySQL, VmTools
2.The Binary Log
3.MySQL主备复制原理、实现及异常处理
4.MySQL binlog格式解析

概述