分析MySQL慢查询的commit慢和binlog中慢事务的区别
常见原因总结，特殊情况除外。
一、问题来源
在分析性能问题的时候慢查询和binlog慢事务是常用的手段。最近在分析一个慢查询的，发现其中包含了大量的commit语句慢，但是在分析binlog慢事务的时候不能完成匹配。比如这段时间commit的语句可能有1000个，但是慢事务可能只有100个，这个差得也太多了，那么为什么会出现这种现象呢？
二、各自的判定方式
-
慢事务 对于一个显示提交的(insert)事务通常如下：
-
GTID_LOG_EVENT和XID_EVENT是命令‘COMMIT’发起的时间。
-
QUERY_EVENT是第一个‘Insert’命令发起的时间。
-
MAP_EVENT/WRITE_ROWS_EVENT是每个‘Insert’命令发起的时间。
因此我们通常通过XID_EVENT的时间减去QUERY_EVENT的时间就得到了一个慢事务时间， 当然如果是自动提交的则不能这么计算 ，因为各个event都是语句发起的时间。
-
commit 慢的可能性
我们知道commit慢最可能的地方在binlog的刷盘或者等待半同步从库ACK，但是binlog中XID EVENT的时间却不包含这部分时间，也就是说binlog慢事务和慢查询中的commit记录的不是一个时间段。
-
简要说明
如果我们以如下事务为例，进行简要说明
insert into it values(10);
commit;
— insert语句执行 -> QUERY_EVENT时间(T1)
— insert语句执行完成,判定insert语句是否为慢查询(T2)
— commit语句执行 -> GTID_LOG_EVENT和XID_EVENT时间(T3)
flush
fsync
—–> 传输binlog (sync_binlog=1)
<—- 等待ACK (rpl_semi_sync_master_wait_point=AFTER_SYNC)
commit
— commit语句执行完成,判定commit语句是否为慢查询(T4)
-
判定insert语句是否慢的标准是T2-T1(-锁时间)
-
判定commit语句是否慢的标准是T4-T3
-
判定慢事务的标准是T3-T1
因此慢事务的判定和慢查询中commit慢的判定几乎没有什么交集，因此出现这种情况也是正常的，下面来证明。
三、证明
-
主库:半同步超时时间为999999999。
-
从库:设置sync_relay_log=1,并且断点设置在MYSQL_BIN_LOG::flush_and_sync函数上，本函数是从库每次event写到relay log后受到 sync_relay_log=1 的影响必须要落盘的判定函数。
这样人为在断点处等待一下就显著的拉长了commit的时间，同时也证明半同步慢会影响commit慢，如下：
select now(); -T1
insert into it values(10);
select sleep(10);
select now(); -T2
commit; (断点在从库生效卡主ack) -T3
select now(); -T4
结果
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> select now(); -T1
+———————+
| now() |
+———————+
| 2022-06-12 22:20:43 |
+———————+
1 row in set (0.00 sec)
mysql> insert into it values(10);
Query OK, 1 row affected (0.10 sec)
mysql> select sleep(10);
+———–+
| sleep(10) |
+———–+
| 0 |
+———–+
1 row in set (10.01 sec)
mysql> select now(); -T2 AND T3
+———————+
| now() |
+———————+
| 2022-06-12 22:20:54 |
+———————+
1 row in set (0.00 sec)
mysql> commit;
Query OK, 0 rows affected (21.64 sec)
mysql> select now(); -T4
+———————+
| now() |
+———————+
| 2022-06-12 22:21:15 |
+———————+
1 row in set (0.00 sec)
我们来分析一下慢查询和binlog，这里加入了sleep(10)拖长了事务commit时间，因为insert太快了。
-
binlog慢事务 22:20:54(T2) – 22:20:43(T1) = 11秒左右(我们加入了sleep(10))
#220612 22:20:54 server id 613306 end_log_pos 12286 CRC32 0x3e019332 GTID last_committed=40 sequence_number=41 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= ‘00320cc8-39f9-11ec-b5ba-000c2929706d:41’/*!*/;
# at 12286
#220612 22:20:43 server id 613306 end_log_pos 12360 CRC32 0x8dcde193 Query thread_id=43 exec_time=1 error_code=0
SET TIMESTAMP=1655043643/*!*/;
BEGIN
/*!*/;
# at 12360
#220612 22:20:43 server id 613306 end_log_pos 12409 CRC32 0x0db68582 Rows_query
# insert into it values(10)
# at 12409
#220612 22:20:43 server id 613306 end_log_pos 12456 CRC32 0x363a48c7 Table_map: `mysemi`.`it` mapped to number 124
# at 12456
#220612 22:20:43 server id 613306 end_log_pos 12496 CRC32 0xd44e43f3 Write_rows: table id 124 flags: STMT_END_F
### INSERT INTO `mysemi`.`it`
### SET
### @1=10 /* INT meta=0 nullable=1 is_null=0 */
# at 12496
#220612 22:20:54 server id 613306 end_log_pos 12527 CRC32 0x4d8d2c64 Xid = 547
COMMIT/*!*/;
-
慢查询中的commit慢 22:21:15(T4) – 22:20:54(T3) = 21秒
# User@Host: root[root] @ localhost [] Id: 43
# Schema: mysemi Last_errno: 0 Killed: 0
# Query_time: 21.641090 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0
# Bytes_sent: 11
SET timestamp=1655043675;
commit;
这里很显然了慢查询记录的commit慢明显不包含在慢事务中。
四、总结
基于如上我们稍微做下总结，并且加上我们常有的认知，总结如下：
-
binlog慢事务中有记录，慢查询没有记录，可能事务中有大量的锁等待信息或者是事务没有及时提交。
-
慢查询有记录，binlog慢事务中没有记录，可能语句本身为自动事务提交，自动提交的事务无法计算慢事务。
-
如果确实是DML语句慢(排除加锁时间)导致的慢事务并且为显示(begin;commit)事务才会同时出现在binlog慢事务和慢查询中。
-
慢查询中出现commit慢和binlog慢事务没有必然的关系，因为记录的时间完全不同。
-
半同步慢ACK和日志刷盘慢会影响到commit慢，都会记录到慢查询（MGR before commit hook 处理慢也会）。
-
如果binlog慢事务和某些慢查询中的select语句时间匹配则可能是事务中包含了select语句导致。
当然这只是常见的总结，很多特殊原因不好说，需要pstack等手段确认。
到此这篇关于MySQL慢查询中的commit慢和binlog中慢事务的差异的文章就介绍到这了,更多相关MySQL慢查询commit和binlog慢事务内容请搜索以前的文章或继续浏览下面的相关文章希望大家以后多多支持！
