mysql binlog日志事件解析

原创

wangwei-dba

修改于 2021-06-10 11:48:39

1.7K0

修改于 2021-06-10 11:48:39

文章被收录于专栏：mysql-dbamysql-dba

二进制日志（binary log）是mysql的一种日志记录了mysql中的数据变更操作，二进制日志主要有以下作用：

1.复制

2.数据恢复

3.日志审计

二进制日志有日志文件和索引文件组成，索引文件（index）记录尚未被清理的二进制日志列表

[root@ck1 logs]# ll
total 16
-rw-r----- 1 mysql mysql  242 Jun  9 11:36 mysql-bin.000003
-rw-r----- 1 mysql mysql 1805 Jun  9 11:39 mysql-bin.000004
-rw-r----- 1 mysql mysql  195 Jun  9 11:39 mysql-bin.000005
-rw-r----- 1 mysql mysql  132 Jun  9 11:39 mysql-bin.index

如下我们用mysqlbinlog来解析二进制，并进行说明：

进行相关的增删改查操作（日志格式row格式并开启的gtid）

/usr/local/mysql/bin/mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS

mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.18    |
+-----------+
1 row in set (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.02 sec)

mysql> show master status ;
+------------------+----------+--------------+------------------+-------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                         |
+------------------+----------+--------------+------------------+-------------------------------------------+
| mysql-bin.000004 |      195 |              |                  | 3d1b92a0-b919-11eb-87db-56c8a95977d1:1-27 |
+------------------+----------+--------------+------------------+-------------------------------------------+
1 row in set (0.00 sec)

mysql> create database testdb;
Query OK, 1 row affected (0.01 sec)
mysql> use testdb;
Database changed
mysql> create table test(id int primary key auto_increment,name varchar(20));
Query OK, 0 rows affected (0.03 sec)

mysql> insert into test(name) values ('binlog'),('rowlog');
Query OK, 2 rows affected (0.02 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> update test set name='binlog_new' where name='binlog';
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> delete from test where name='binlog_new';
Query OK, 1 row affected (0.01 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.02 sec)

mysql> show master status ;
+------------------+----------+--------------+------------------+-------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                         |
+------------------+----------+--------------+------------------+-------------------------------------------+
| mysql-bin.000005 |      195 |              |                  | 3d1b92a0-b919-11eb-87db-56c8a95977d1:1-32 |
+------------------+----------+--------------+------------------+-------------------------------------------+
1 row in set (0.00 sec)

解析：
[root@ck1 logs]# /usr/local/mysql/bin/mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS mysql-bin.000004 > 4.sql

每个二进制日志文件以4个字节的魔术数开始，后面包含各种用于表示mysql数据的变更事件

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;

设置系统变量

# at 4
#210609 11:36:17 server id 2223306  end_log_pos 124 CRC32 0x0fd60233    Start: binlog v 4, server v 8.0.18 created 210609 11:36:17

# at 4 为事件在二进制日志文件中的偏移量，单位字节

#21060911:36:17 该事件的写入时间

server id 2223306 产生该时间的mysql的server id

end_log_pos 124 表示该事件结束的偏移量124，下一个事件起始偏移量为124

binlog v 4 二进制日志结构的版本为v4

server v 8.0.18 mysql的版本为8.0.18

created 21060911:36:17 表示该二进制日志的创建时间（start表示该事件的类型为Format_description_event为第一个事件，该事件的创建时间和二进制日志文件创建时间一致）

二进制日志的第一个事件是Format_description_event类型事件，记录二进制日志的版本，数据库版本，文件创建时间（binlog v 4, server v 8.0.18 created 21060911:36:17）

# at 124
#210609 11:36:17 server id 2223306  end_log_pos 195 CRC32 0xe68c4ab6    Previous-GTIDs
# 3d1b92a0-b919-11eb-87db-56c8a95977d1:1-27

Previous-GTIDs表示该事件为Previous_gtid_log_event类型事件，在mysql切换新的二进制日志文件时会写入此事件，用于记录创建该日志文件之前执行的全局事务id的集合

# at 386
#210609 11:37:44 server id 2223306  end_log_pos 463 CRC32 0x18bc8e52    GTID    last_committed=1 
 sequence_number=2       rbr_only=no     original_committed_timestamp=1623209864107514   
 immediate_commit_timestamp=1623209864107514     transaction_length=238
# original_commit_timestamp=1623209864107514 (2021-06-09 11:37:44.107514 CST)
# immediate_commit_timestamp=1623209864107514 (2021-06-09 11:37:44.107514 CST)
/*!80001 SET @@session.original_commit_timestamp=1623209864107514*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= '3d1b92a0-b919-11eb-87db-56c8a95977d1:29'/*!*/;

GTID 表示该事件类型为Gtid_log_event，该事件记录了事务的Gtid

last_committed=1，表示该二进制日志文件中最大的已提交事务的sequence_number,当有多个事务同时提交时，这些事务的最大sequence_number是一样的，也就是last_committed一样，这是为并行复制设计的

sequence_number=2 单个二进制日志文件中sequence_number是从1开始，每个事务递增1，表示事务的顺序

SET @@SESSION.GTID_NEXT 表示在会话级别设置该事务的GTID

# at 463
#210609 11:37:44 server id 2223306  end_log_pos 624 CRC32 0xb3e84d8d    Query   thread_id=11    
exec_time=0     error_code=0    Xid = 20
use `testdb`/*!*/;
SET TIMESTAMP=1623209864/*!*/;
/*!80013 SET @@session.sql_require_primary_key=0*//*!*/;
create table test(id int primary key auto_increment,name varchar(20))
/*!*/;

Query 表示该事件为Query_log_event事件

thread_id=11 执行该语句的线程id

exec_time=0 执行该语句的时间

error_code=0 执行该语句返回的错误码

SET TIMESTAMP= 设置事件时间戳

# at 703
#210609 11:38:30 server id 2223306  end_log_pos 780 CRC32 0x506c8335    Query   thread_id=11    
exec_time=0     error_code=0
SET TIMESTAMP=1623209910/*!*/;
BEGIN
/*!*/;

Query 表示该事件为Query_log_event事件

# at 780
#210609 11:38:30 server id 2223306  end_log_pos 855 CRC32 0x5beb0b5a    Rows_query
# insert into test(name) values ('binlog'),('rowlog')

Rows_query表示事件为Rows_query_log_event类型，记录数据变更的原始语句，需要设置binlog_rows_query_log_events = on才会记录该事件

# at 855
#210609 11:38:30 server id 2223306  end_log_pos 913 CRC32 0x28356463    Table_map: `testdb`.`test` 
mapped to number 87

Table_map：表示该事件为Table_map_event类型事件，记录发生变更操作的表结构

# at 913
#210609 11:38:30 server id 2223306  end_log_pos 972 CRC32 0xf2220a01    Write_rows: table id 87 
flags: STMT_END_F
### INSERT INTO `testdb`.`test`
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='binlog' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */
### INSERT INTO `testdb`.`test`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='rowlog' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */

Write_rows：表示该事件的类型为Write_rows_log_event 对应数据的insert操作

table id 87 ：insert插入表的tableid 87，通过此id从上个事件table_map获取表的结构信息

flags: STMT_END_F：STMT_END_F表示当前最后一个insert事件

下面的insert语句时插入的具体内容

@1表示插入的第一个字段，注释中表示字段类型，元数据，是否为空

# at 972
#210609 11:38:30 server id 2223306  end_log_pos 1003 CRC32 0xf2d2f493   Xid = 21
COMMIT/*!*/;

Xid：表示次事件类型为Xid_event 表示事务提交

Xid =21：该事务的xid为21，在mysql异常恢复阶段，mysql会解析redo日志中处于prepare状态的事务，得到xid,然后根据xid在二进制日志中查找，如果找到匹配的xid则对事务进行重新持久化，否则回滚事务

# at 1303
#210609 11:39:06 server id 2223306  end_log_pos 1367 CRC32 0xeaabcd3a   Update_rows: table id 87
 flags: STMT_END_F
### UPDATE `testdb`.`test`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='binlog' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='binlog_new' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */

Update_rows：表示该事件的类型为Update_rows_log_event 记录数据的update操作

# at 1676
#210609 11:39:34 server id 2223306  end_log_pos 1727 CRC32 0xa82ecc61   Delete_rows: table id 87
 flags: STMT_END_F
### DELETE FROM `testdb`.`test`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='binlog_new' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */

Delete_rows：表示该事件为Delete_rows_log_event,记录delete操作的实际数据

mysql事件总结：

Format_description_event：记录二进制日志的版本，数据库版本，文件创建时间

Previous_gtid_log_event：创建该日志文件之前执行的全局事务id的集合

Gtid_log_event：该事件记录了事务的Gtid

Query_log_event：记录执行语句，一般为DDL

Rows_query_log_event：记录数据变更的原始语句

Table_map_event：记录发生变更操作的表结构

Write_rows_log_event ：对应数据的insert操作

Xid：表示事务提交，后期用于mysql崩溃恢复

Update_rows_log_event ：记录数据的update操作

Delete_rows_log_event：记录delete操作的实际数据