今天在分析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
#2110280: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= /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=0 (1970-01-0108:00:00.000000 CST)
# immediate_commit_timestamp=0 (1970-01-0108:00:00.000000 CST)
/*!80001 SET @@iginal_commit_timestamp=0*//*!*/;
/*!80014 SET @@iginal_server_version=0*//*!*/;
/*!80014 SET @@session.immediate_server_version=0*//*!*/;
SET @@SESSION.GTID_NEXT= '57f83e26-e388-11eb-8cec-0c42a1da302e:60182044'/*!*/;
# at 197793759
#2110280: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
#2110280:08:22 server id 719042933 end_log_pos 197796409 CRC32 0x13dce102 Xid = 493500574
COMMIT/*!*/;广告宣传栏制作
# at 197796409
#2110280: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= /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=0 (1970-01-0108:00:00.000000 CST)
# immediate_commit_timestamp=0 (1970-01-0108:00:00.000000 CST)
/*!80001 SET @@iginal_commit_timestamp=0*//*!*/;
/*!80014 SET @@iginal_server_version=0*//*!*/;
/*!80014 SET @@session.immediate_server_version=0*//*!*/;
SET @@SESSION.GTID_NEXT= '57f83e26-e388-11eb-8cec-0c42a1da302e:60182045'/*!*/;
# at 197796474
#2110280: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研磨网
#2110280:08:20 server id 719042933 end_log_pos 197796655 CRC32 0xa2a83d91 Table_map: `tt`.`tt` mapped to number 4034
# at 197796655
#2110280: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'/* 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
#2110280: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 select2;
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
#2110289: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
#2110289: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
#2110289: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
#2110289:45:37 server id 3357 end_log_pos 673 CRC32 0x2c52aa61 Table_map: `ceshi`.`tt` mapped to number 120
# at 673
#2110289: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
#2110289: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
豫公网安备41160202000603
站长QQ:729038198
关于我们
投诉建议