在分析效能問題的時候慢查詢和binlog慢事務是常用的手段。最近在分析一個慢查詢的，發現其中包含了大量的commit語句慢，但是在分析binlog慢事務的時候不能完成配對。例如這段時間commit的語句可能有1000個，但是慢事務可能只有100個，這個差得也太多了，那為什麼會出現這種現象呢？
慢交易對於一個顯示提交的(insert)事務通常如下：
GTID_LOG_EVENT和XID_EVENT是指令‘COMMIT’發起的時間。
第一個啟動"INSERT"指令的時間是QUERY_EVENT。
MAP_EVENT/WRITE_ROWS_EVENT是每個‘Insert’命令發起的時間。
因此我們通常透過XID_EVENT的時間減去QUERY_EVENT的時間就得到了一個慢事務時間， 當然如果是自動提交的則不能這麼計算 ，因為各個event都是語句發起的時間。
commit 慢的可能性
我們知道commit慢最可能的地方在binlog的刷盤或等待半同步從庫ACK，但是binlog中XID EVENT的時間卻不包含這部分時間，也就是說binlog慢事務和慢查詢中的commit記錄的不是一個時間段。
簡單說明
如果我們以下列事務為例，請簡單說明
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(); -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))
# 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=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秒
# 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: 11 SET timestamp=1655043675; commit;
這裡很顯然了慢查詢記錄的commit慢明顯不包含在慢事務中。
以上是MySQL慢查詢中的commit慢和binlog中慢事務有什麼差別的詳細內容。更多資訊請關注PHP中文網其他相關文章！
