binlog内容时间乱序问题排查

今天在分析binlog长事务，无间看到 binlog 文件中，记录时间竟然乱序了，

0:08:22 先写的binlog

0:08:20 后写的binlog，而且exec_time=8 秒，这个也不正常。
exec_time记录DDL命令执行时间是正确的，记录DML操作不太准确，它取值是SQL访问到第一条记录所需时间（意思是一条SQL更新100W条记录耗时100秒，但访问到第一条记录只用了0.01秒，此时exec_time取值是0）

# at 197793694
#211028  0:08:22 server id 719042933  end_log_pos 197793759 CRC32 0x3ab5dcf2     GTID    last_committed=118090    sequence_number=118092    rbr_only=yes    original_committed_timestamp=0    immediate_commit_timestamp=0    transaction_length=0
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=0 (1970-01-01 08:00:00.000000 CST)
# immediate_commit_timestamp=0 (1970-01-01 08:00:00.000000 CST)
/*!80001 SET @@session.original_commit_timestamp=0*//*!*/;
/*!80014 SET @@session.original_server_version=0*//*!*/;
/*!80014 SET @@session.immediate_server_version=0*//*!*/;
SET @@SESSION.GTID_NEXT= '57f83e26-e388-11eb-8cec-0c42a1da302e:60182044'/*!*/;
# at 197793759
#211028  0:08:22 server id 719042933  end_log_pos 197793844 CRC32 0xacbb9a0e     Query    thread_id=5428006    exec_time=0    error_code=0
SET TIMESTAMP=1635350902/*!*/;
BEGIN
/*!*/;
# at 197793844
# at 197794017
# at 197794558
# at 197794740
# at 197795036
# at 197795130
# at 197796044
# at 197796149
# at 197796378
#211028  0:08:22 server id 719042933  end_log_pos 197796409 CRC32 0x13dce102     Xid = 493500574
COMMIT/*!*/;
# at 197796409
#211028  0:08:20 server id 719042933  end_log_pos 197796474 CRC32 0x1507d629     GTID    last_committed=118090    sequence_number=118093    rbr_only=yes    original_committed_timestamp=0    immediate_commit_timestamp=0    transaction_length=0
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=0 (1970-01-01 08:00:00.000000 CST)
# immediate_commit_timestamp=0 (1970-01-01 08:00:00.000000 CST)
/*!80001 SET @@session.original_commit_timestamp=0*//*!*/;
/*!80014 SET @@session.original_server_version=0*//*!*/;
/*!80014 SET @@session.immediate_server_version=0*//*!*/;
SET @@SESSION.GTID_NEXT= '57f83e26-e388-11eb-8cec-0c42a1da302e:60182045'/*!*/;
# at 197796474
#211028  0:08:20 server id 719042933  end_log_pos 197796560 CRC32 0x98c9f35b     Query    thread_id=5429012    exec_time=8    error_code=0
SET TIMESTAMP=1635350900/*!*/;
BEGIN
/*!*/;
# at 197796560
#211028  0:08:20 server id 719042933  end_log_pos 197796655 CRC32 0xa2a83d91     Table_map: `tt`.`tt` mapped to number 4034
# at 197796655
#211028  0:08:20 server id 719042933  end_log_pos 197796828 CRC32 0x89461f2a     Write_rows_v1: table id 4034 flags: STMT_END_F
### INSERT INTO `dataengine`.`risk_user_info`
### SET
###   @1=460139 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='241231605760438272' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @3='' /* VARSTRING(80) meta=80 nullable=0 is_null=0 */
###   @4='U6172C57989D8880001323A9B' /* VARSTRING(200) meta=200 nullable=0 is_null=0 */
###   @5='3171085310830003' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
###   @6='+6281223236435' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
###   @7='citrahanis13@gmail.com' /* VARSTRING(400) meta=400 nullable=1 is_null=0 */
###   @8=NULL /* VARSTRING(400) meta=400 nullable=1 is_null=1 */
###   @9=NULL /* VARSTRING(80) meta=80 nullable=1 is_null=1 */
###   @10=1635350900.949 /* TIMESTAMP(3) meta=3 nullable=0 is_null=0 */
###   @11=1635350900.949 /* TIMESTAMP(3) meta=3 nullable=0 is_null=0 */
###   @12=NULL /* VARSTRING(80) meta=80 nullable=1 is_null=1 */
# at 197796828
#211028  0:08:20 server id 719042933  end_log_pos 197796859 CRC32 0xb864a344     Xid = 493500493
COMMIT/*!*/;

之前遇到过长事务的binlog，xid 时间和执行SQL时间不一致。

通过binlog内容中 exec_time=8 ，怀疑这个sql执行时遇到的锁等待，所以它可能是最先执行的，但并不是最先提交的。

尝试复现这个场景，

session1 （创建两表 tt  和 vv，并为 tt 表所有记录加排它锁）:

mysql> create table vv(id int primary key);
Query OK, 0 rows affected (0.02 sec)

mysql> insert into vv select 1;
Query OK, 1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0

mysql> create table tt(id int primary key);
Query OK, 0 rows affected (0.02 sec)

mysql> insert into tt values(1),(2),(3),(4),(5);
Query OK, 5 rows affected (0.01 sec)
Records: 5  Duplicates: 0  Warnings: 0

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from tt for update;
+----+
| id |
+----+
|  1 |
|  2 |
|  3 |
|  4 |
|  5 |
+----+
5 rows in set (0.00 sec)

session2 （切换一次binlog，删除记录）:

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

mysql> delete from tt where id=5;  (此时处于锁等待)

session3 (向 vv 表写入记录)：

mysql> insert into vv select 2;
Query OK, 1 row affected (0.00 sec)
Records: 1  Duplicates: 0  Warnings: 0

session1 （释放锁资源，让session2写入成功）:

mysql> rollback;
Query OK, 0 rows affected (0.00 sec)

分析binlog内容：

09:45:52 时间写入 vv 表的记录在前，

09:45:37 时间删除 tt 表 id=5 的记录在后边。 

# at 372
#211028  9:45:52 server id 3357  end_log_pos 418 CRC32 0x78af715c       Table_map: `ceshi`.`vv` mapped to number 121
# at 418
#211028  9:45:52 server id 3357  end_log_pos 458 CRC32 0x13feb395       Write_rows: table id 121 flags: STMT_END_F

BINLOG '
UHF6YRMdDQAALgAAAKIBAAAAAHkAAAAAAAEABWNlc2hpAAJ2dgABAwAAXHGveA==
UHF6YR4dDQAAKAAAAMoBAAAAAHkAAAAAAAEAAgAB//4CAAAAlbP+Ew==
'/*!*/;
### INSERT INTO `ceshi`.`vv`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
# at 458
#211028  9:45:52 server id 3357  end_log_pos 489 CRC32 0x53acf6fd       Xid = 128
COMMIT/*!*/;
# at 489
#211028  9:45:37 server id 3357  end_log_pos 554 CRC32 0xf7375c01       GTID    last_committed=1        sequence_number=2       rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '403ce25f-1463-11ec-8f1f-060ce27ba514:590'/*!*/;
# at 554
#211028  9:45:37 server id 3357  end_log_pos 627 CRC32 0x3372ffe9       Query   thread_id=7     exec_time=33    error_code=0
SET TIMESTAMP=1635414337/*!*/;
BEGIN
/*!*/;
# at 627
#211028  9:45:37 server id 3357  end_log_pos 673 CRC32 0x2c52aa61       Table_map: `ceshi`.`tt` mapped to number 120
# at 673
#211028  9:45:37 server id 3357  end_log_pos 713 CRC32 0xbf93f28b       Delete_rows: table id 120 flags: STMT_END_F

BINLOG '
QXF6YRMdDQAALgAAAKECAAAAAHgAAAAAAAEABWNlc2hpAAJ0dAABAwAAYapSLA==
QXF6YSAdDQAAKAAAAMkCAAAAAHgAAAAAAAEAAgAB//4FAAAAi/KTvw==
'/*!*/;
### DELETE FROM `ceshi`.`tt`
### WHERE
###   @1=5 /* INT meta=0 nullable=0 is_null=0 */
# at 713
#211028  9:45:37 server id 3357  end_log_pos 744 CRC32 0x65dacdb7       Xid = 127
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file