MySQL 优化之：慢查询中的commit慢和binlog中慢事务的差异 - 主机乐

begin;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慢，如下：

begin;select now();   -T1insert into it values(10);select sleep(10);select now();   -T2commit; (断点在从库生效卡主ack) -T3select 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))

# at 12221#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=0SET 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 = 547COMMIT/*!*/;

慢查询中的commit慢 22:21:15(T4) – 22:20:54(T3) = 21秒

# Time: 2022-06-12T22:21:15.746223Z# 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: 11SET timestamp=1655043675;commit;

这里很显然了慢查询记录的commit慢明显不包含在慢事务中。