mysql binlog日志解析
1、什么是binlog
MySQL Server 有四种类型的日志——Error Log、General Query Log、Binary Log 和 Slow Query Log。
- Error Log:错误日志,记录 mysqld 的一些错误。
- General Query Log:一般查询日志,记录 mysqld 正在做的事情,比如客户端的连接和断开、来自客户端每条 Sql Statement 记录信息;如果你想准确知道客户端到底传了什么瞎 [哔哔] 玩意儿给服务端,这个日志就非常管用了,不过它非常影响性能。
- Slow Query Log:是慢查询日志,记录一些查询比较慢的 SQL 语句——这种日志非常常用,主要是给开发者调优用的。
- Binary Log:就是 Binlog 了,binlog是一个二进制格式的文件,用于记录用户对数据库更新的SQL语句信息。binlog包含了一些事件,这些事件描述了数据库的改动,如建表、数据改动等,也包括一些潜在改动,比如 DELETE FROM ran WHERE bing = luan,然而一条数据都没被删掉的这种情况。除非使用 Row-based logging,否则会包含所有改动数据的 SQL Statement。
显然,我们执行SELECT等不设计数据变更的语句是不会记录Binlog的,而涉及到数据更新则会记录。要注意的是,对支持事务的引擎如InnoDB而言,必须要提交了事务才会记录Binlog。Binlog是在事务最终commit前写入的,binlog什么时候刷新到磁盘跟参数sync_binlog相关。如果设置为0,则表示MySQL不控制binlog的刷新,由文件系统去控制它缓存的刷新,而如果设置为不为0的值则表示每sync_binlog次事务,MySQL调用文件系统的刷新操作刷新binlog到磁盘中。设为1是最安全的,在系统故障时最多丢失一个事务的更新,但是会对性能有所影响,一般情况下会设置为100或者0,牺牲一定的一致性来获取更好的性能。
默认情况下,binlog日志是二进制格式的,不能使用查看文本工具的命令(比如,cat,vi等)查看,而使用mysqlbinlog解析查看。
2.binlog的作用
当有数据写入到数据库时,还会同时把更新的SQL语句写入到对应的binlog文件里,这个文件就是上文说的binlog文件。使用mysqldump备份时,只是对一段时间的数据进行全备,但是如果备份后突然发现数据库服务器故障,这个时候就要用到binlog的日志了。
主要作用是用于数据库的主从复制及数据的增量恢复。
3、开启和停用Binlog
在mysql的配置文件my.cnf中,增加log_bin参数即可开启binlog日志
[mysqld]
log-bin=mysql-bin
可以通过赋值来指定binlog日志的文件名,实例如下:
[root@db02 ~]# mkdir /application/mysql/logs [root@db02 ~]# chown -R mysql.mysql /application/mysql/logs 开启binlog 编辑/etc/my.cnf [mysqld] log_bin = /application/mysql/logs/dadong-bin
#这个需要重启MySQL服务。 重启:/etc/init.d/mysqld restart
[root@db02 ~]# ll /application/mysql/logs/ total 8 -rw-rw---- 1 mysql mysql 120 Jun 21 12:04 dadong-bin.000001 -rw-rw---- 1 mysql mysql 42 Jun 21 12:04 dadong-bin.index
为什么要刷新binlog?找到全备数据和binlog文件的恢复临界点.
如何刷新
每天晚上0点备份数据库
mysqldump -A -B -F >/opt/$(date +%F).sql
[root@db02 ~]# ll /application/mysql/logs/
-rw-rw---- 1 mysql mysql 168 Jun 21 12:06 dadong-bin.000001
-rw-rw---- 1 mysql mysql 168 Jun 21 12:06 dadong-bin.000002
-rw-rw---- 1 mysql mysql 210 Jun 21 12:07 dadong-bin.index
提示:每个库刷新一次.
可以使用SET SQL_LOG_BIN=0命令停止使用日志文件,然后可以通过SET SQL_LOG_BIN=1命令来启用。
4、Binlog的删除
mysql> show variables like 'expire_log_days'; mysql> set global 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 logs to 'binlog.000002';//删除指定日志文件
除了以上方法之外,也可以采用操作系统的本地命令删除文件。
5、Binlog文件的扩展
当遇到以下3种情况时会重新生成一个新的日志文件,文件序号递增:
- MySQL服务器停止或重启时,MySQL会在重启时生成一个新的日志文件;
- 使用flush logs命令;
- 当binlog文件大小超过max_binlog_size系统变量配置的上限时;
注:binlog文件的最大值和默认值是1GB,该设置并不能严格控制binlog的大小,尤其是binlog比较靠近最大值而又遇到一个比较大事务时,为了保证事务的完整性,不可能做切换日志的动作,只能将该事务的所有SQL都记录到当前日志,直到事务结束。
6、Binlog的日志格式
binlog有三种格式:Statement, Row和Mixed.
- 基于SQL语句的复制(statement-based replication, SBR)
- 基于行的复制(row-based replication, RBR)
- 混合模式复制(mixed-based replication, MBR)
(1)Statement
每一条会修改数据的sql都会记录在binlog中。
优点:不需要记录每一行的变化,减少了binlog日志量,节约了IO, 提高了性能。
缺点:由于记录的只是执行语句,为了这些语句能在slave上正确运行,因此还必须记录每条语句在执行的时候的一些相关信息,以保证所有语句能在slave得到和在master端执行的时候相同的结果。另外mysql的复制,像一些特定函数的功能,slave可与master上要保持一致会有很多相关问题。
相比row能节约多少性能与日志量,这个取决于应用的SQL情况,正常同一条记录修改或者插入row格式所产生的日志量还小鱼statement产生的日志量,但是考虑到如果带条件的update操作,以及整表删除,alter表等操作,row格式会产生大量日志,因此在考虑是否使用row格式日志时应该根据应用的实际情况,其所产生的日志量会增加多少,以及带来的IO性能问题。
(2)Row
5.1.5版本的MySQL才开始支持row level的复制,它不记录sql语句上下文相关信息,仅保存哪条记录被修改。
优点: binlog中可以不记录执行的sql语句的上下文相关的信息,仅需要记录那一条记录被修改成什么了。所以row的日志内容会非常清楚的记录下每一行数据修改的细节。而且不会出现某些特定情况下的存储过程,或function,以及trigger的调用和触发无法被正确复制的问题.
缺点:所有的执行的语句当记录到日志中的时候,都将以每行记录的修改来记录,这样可能会产生大量的日志内容。
新版本的MySQL中对row level模式也被做了优化,并不是所有的修改都会以row level来记录,像遇到表结构变更的时候就会以statement模式来记录,如果sql语句确实就是update或者delete等修改数据的语句,那么还是会记录所有行的变更。
(3)Mixed
从5.1.8版本开始,MySQL提供了Mixed格式,实际上就是Statement与Row的结合。
在Mixed模式下,一般的语句修改使用statment格式保存binlog,如一些函数,statement无法完成主从复制的操作,则采用row格式保存binlog,MySQL会根据执行的每一条具体的sql语句来区分对待记录的日志形式,也就是在Statement和Row之间选择一种。
7、查看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 events in '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 */ | +------------------+-----+-------------+-----------+-------------+---------------------------------------+ 17 rows in set (0.00 sec)
或者使用mysqlbinlog命令,在shell终端输入(假设当前目录为 ../mysql/data): ../bin/mysqlbinlog mysql-bin.000005
[root@xxx data]# pwd /usr/local/mysql/data [root@xxx 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 .....
8、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的事件类型一共有以下几种:
enum Log_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 */ };
现在(从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:
一个新的binlog文件都是以FORMAT_DESCRIPTION_EVENT开始的(v4版)。这里就以FORMAT_DESCRIPTION_EVENT为例来解析下(mysql-bin.000005)。通过hexdump -C mysql-bin.000005来查看二进制文件。(下面只列出部分内容)
[root@xxx data]# hexdump -C mysql-bin.000005 00000000 fe 62 69 6e f1 34 08 58 0f 02 00 00 00 67 00 00 |.bin.4.X.....g..| 00000010 00 6b 00 00 00 01 00 04 00 35 2e 35 2e 35 31 2d |.k.......5.5.51-| 00000020 6c 6f 67 00 00 00 00 00 00 00 00 00 00 00 00 00 |log.............| 00000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| 00000040 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 13 |................| 00000050 38 0d 00 08 00 12 00 04 04 04 04 12 00 00 54 00 |8.............T.| 00000060 04 1a 08 00 00 00 08 08 08 02 00 42 35 08 58 02 |...........B5.X.| 00000070 02 00 00 00 4a 00 00 00 b5 00 00 00 08 00 a2 00 |....J...........| 00000080 00 00 01 00 00 00 0a 00 00 1a 00 00 00 00 00 00 |................| 00000090 01 00 00 00 00 00 00 00 00 06 03 73 74 64 04 21 |...........std.!|
按照官方文档中的说明来看下FORMAT_DESCRIPTION_EVENT格式:
v4 format description event
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格式解析
————————————————
版权声明:本文为CSDN博主「朱小厮」的原创文章,遵循 CC 4.0 BY-SA 版权协议,转载请附上原文出处链接及本声明。
原文链接:https://blog.csdn.net/u013256816/article/details/53020335