MySQL事务日志event乱序验证

  • 服务器环境
  1. 操作系统版本:CentOS release 7.5 (Final)

  2. MySQL 版本:Oracle MySQL 5.7.30

  3. MySQL 关键参数:innodb_flush_log_at_trx_commit=1; sync_binlog=1; binlog_format=row; gtid_mode=on; enforce_gtid_consistency=on

  4. 验证所需数据:sysbench 压测之后遗留的测试数据( 可自行造数,只需要一张表中有一条数据即可 )

一、先决条件

  • 登录到数据库中,手动滚动一下binlog文件
mysql> flush logs;select now();
Query OK, 0 rows affected (0.22 sec)

+---------------------+
| now()               |
+---------------------+
| 2020-08-20 14:37:24 |       # 滚动 binlog 的时间点为2020-08-20 14:37:24
+---------------------+
1 row in set (0.00 sec)
  • 解析一下最新的Binlog文件中的内容及其对应的时间点信息
[root@centos ~]# /data/mysql/base/5.7.30/bin/mysqlbinlog -vvv --base64-output=decode-rows /data/mysql/log/binlog/3306/mysql-bin.000011 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#200820 14:37:23 server id 1597281560  end_log_pos 123 CRC32 0x0e9ca4d1     Start: binlog v 4, server v 5.7.30-log created 200820 14:37:23
# Warning: this binlog is either in use or was not closed properly.
# at 123
#200820 14:37:23 server id 1597281560  end_log_pos 194 CRC32 0x4bcad90b     Previous-GTIDs
# 049f1f26-dd03-11ea-bc16-02000aba3c36:1-303264
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 的解析内容来看,当前最新的 binlog 中,除了文件头的 event 之外,并没有其他用户数据产生的 event 数据,且文件头的所有 event 的时间点都为 2020-08-20 14:37:23,这个时间点也是在数据库中手动执行 binlog 滚动语句的时间点,也就是说:binlog 文件头的 event 是在 binlog 滚动时就已经产生且写入到了最新的 binlog 中,且这些event与用户数据无关。

二、操作过程

  • 接下来我们模拟用户对数据执行 update 操作,且为了验证需要,我们使用了显式事务,且在事务执行过程中人为加入了停顿,以便更清晰地看到 binlog 中的 event 是如何记录的。

  • 首先,登录到数据库中,显式开启一个事务。

# 查询测试数据,以便后续编写 update 语句
mysql> select * from t1 limit 1;
+----+------+
| id | name |
+----+------+
|  1 | aa   |
+----+------+
1 row in set (0.00 sec)

# 显示的开启一个事务
mysql> begin;select now();
Query OK, 0 rows affected (0.00 sec)

+---------------------+
| now()               |
+---------------------+
| 2020-08-20 14:49:32 |       # begin 语句时间点为 2020-08-20 14:49:32
+---------------------+
1 row in set (0.00 sec)
  • 这个时候,binlog 中还未记录新事务的 binlog 日志,等待几十秒之后,再在数据库中执行 update 语句修改 name 列值.
mysql> update t1 set name = 'qqqq' where id = 1;   select now();
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

+---------------------+
| now()               |
+---------------------+
| 2020-08-20 14:51:10 |      # update语句执行的时间点为 2020-08-20 14:51:10
+---------------------+
1 row in set (0.00 sec)
  • 这个时候,binlog 中仍然还未记录新事务的 binlog 日志( 因为事务并没有提交,binlog 只会在事务提交时才会写入 binlog 文件中),现在,我们对该显式事务执行 commit 语句提交事务。
mysql> commit;select now();
Query OK, 0 rows affected (0.00 sec)

+---------------------+
| now()               |
+---------------------+
| 2020-08-20 14:52:16 |      # commit 语句执行的时间点为 2020-08-20 14:52:16
+---------------------+
1 row in set (0.00 sec)

三、解析过程

  • 现在,我们解析最新的 binlog 文件,查看此时 binlog 中是如何记录该事务产生的 event 数据的( 注意:binlog 中每个event的时间点信息是在生成 event 的时候产生的),为了方便阅读,后续内容将对 binlog 做分段说明。

  • 解析命令

[root@centos ~]# /data/mysql/base/5.7.30/bin/mysqlbinlog -vvv --base64-output=decode-rows /data/mysql/log/binlog/3306/mysql-bin.000011
  • 以下内容为 binlog 文件头,event 时间点为手工滚动 binlog 的时间点 2020-08-20 14:37:23,这里并未有任何变化。
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#200820 14:37:23 server id 1597281560  end_log_pos 123 CRC32 0x0e9ca4d1     Start: binlog v 4, server v 5.7.30-log created 200820 14:37:23
# Warning: this binlog is either in use or was not closed properly.
# at 123
#200820 14:37:23 server id 1597281560  end_log_pos 194 CRC32 0x4bcad90b     Previous-GTIDs
# 049f1f26-dd03-11ea-bc16-02000aba3c36:1-303264
  • Position at 194 事务的第一个 event ,是用于记录事务的 GTID 的 event,时间点为 2020-08-20 14:52:16。通过我们事务操作时记录的时间信息,该时间为执行 commit 语句的时间点
# at 194
#200820 14:52:16 server id 1597281560  end_log_pos 259 CRC32 0xc0094738     GTID    last_committed=0    sequence_number=1   rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '049f1f26-dd03-11ea-bc16-02000aba3c36:303265'/*!*/;
  • Position at 259 事务的第二个 event ,是用于记录事务的 begin; 语句的event,时间点为2020-08-20 14:51:10

  • 通过我们事务操作时记录的时间信息,该时间为执行update语句的时间点 2020-08-20 14:51:10,并不是执行 begin; 语句的时间点 2020-08-20 14:49:32,说明该 begin event 是在执行 update 语句时产生,并不是在执行 begin; 语句时产生的。

# at 259
#200820 14:51:10 server id 1597281560  end_log_pos 333 CRC32 0x7dc3489c     Query   thread_id=152   exec_time=0 error_code=0
SET TIMESTAMP=1597906270/*!*/;
SET @@session.pseudo_thread_id=152/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
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=45/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
  • Position at 333 事务的第三个 event,用于记录事务执行的原始 SQL 语句( 需要启用参数:binlog_rows_query_log_events = on ),时间点仍然是执行 update 语句的时间点( 2020-08-20 14:51:10 ),说明该 event 也是在执行 update 语句时产生
# at 333
#200820 14:51:10 server id 1597281560  end_log_pos 397 CRC32 0xf76dc5b2     Rows_query
# update t1 set name = 'qqqq' where id = 1
  • Position at 397 事务的第四个 event,用于记录事务对应的操作表在内存中的映射 ID,时间点仍然是执行 update 语句的时间点( 2020-08-20 14:51:10 ),说明该 event 也是在执行 update 语句时产生
# at 397
#200820 14:51:10 server id 1597281560  end_log_pos 447 CRC32 0x37c45256     Table_map: `testdb`.`t1` mapped to number 223
  • Position at 447 事务的第五个 event,用于记录事务的完整操作语句和数据记录,也就是真正在执行 update 语句做数据修改( 时间点仍然是 2020-08-20 14:51:10 ),说明该 event 也是在执行 update 语句时产生
# at 447
#200820 14:51:10 server id 1597281560  end_log_pos 501 CRC32 0x7a46c005     Update_rows: table id 223 flags: STMT_END_F
### UPDATE `testdb`.`t1`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='aa' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='qqqq' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
  • Position at 501 事务的第六个 event,用于记录事务的 commit 语句,时间点为 2020-08-20 14:52:16,通过我们事务操作时记录的时间信息,该时间为执行 commit 语句的时间点,说明该 event 是在执行 commit 语句时产生的
# at 501
#200820 14:52:16 server id 1597281560  end_log_pos 532 CRC32 0x3ea888e1     Xid = 6060171
COMMIT/*!*/;
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 解析内容中,用户事务的 event 有 GTID ( 记录事务GTID )、Query( 记录事务begin;语句 )、Rows_query( 在row格式下记录事务原始SQL语句 )、Table_map( 记录事务操作表在内存中的映射ID )、Update_rows( 记录事务真正操作的语句和修改的具体数据记录 )、xid( 记录事务commit;语句 )几种类型,其中:

  • GTID 和 xid 类型的 event 是在事务执行 commit 语句时产生的。

  • Query、Rows_query、Table_map、Update_rows 类型的 event 是在事务执行 update 语句时产生的。

  • 执行 begin; 语句时未产生任何 event。

  • 本案例分析到此结束,留一个思考题给大家吧( 大家可以依样画葫芦 )。如果是主从架构,那么:

    • 从库的 relay log 中的 event 时间点会不会与主库 binlog 中记录的相同事务( 这里指GTID相同 )event 时间点不同?
    • 从库如果启用了 log_slave_updates=ON 参数,从库自身的 binlog 中记录的复制事务的 event 会不会与主库 binlog 中记录的相同事务( 这里指GTID相同 ) event 时间点不同?
    • 如果主库存在并发事务,那么主库的 binlog 中记录的 event 时间点又是怎样的呢?
「点点赞赏,手留余香」

    还没有人赞赏,快来当第一个赞赏的人吧!
MySQL
0 条回复 A 作者 M 管理员
    所有的伟大,都源于一个勇敢的开始!
欢迎您,新朋友,感谢参与互动!欢迎您 {{author}},您在本站有{{commentsCount}}条评论