快捷導(dǎo)航

MySQL慢查詢中的commit慢和binlog中慢事務(wù)的區(qū)別

更新時(shí)間：2022年06月15日 10:23:49 作者：yangyidba

這篇文章主要介紹了MySQL慢查詢中的commit慢和binlog中慢事務(wù)的差異,本文給大家介紹的非常詳細(xì)，對(duì)大家的學(xué)習(xí)或工作具有一定的參考借鑒價(jià)值，需要的朋友可以參考下

一、問題來(lái)源

在分析性能問題的時(shí)候慢查詢和binlog慢事務(wù)是常用的手段。最近在分析一個(gè)慢查詢的，發(fā)現(xiàn)其中包含了大量的commit語(yǔ)句慢，但是在分析binlog慢事務(wù)的時(shí)候不能完成匹配。比如這段時(shí)間commit的語(yǔ)句可能有1000個(gè)，但是慢事務(wù)可能只有100個(gè)，這個(gè)差得也太多了，那么為什么會(huì)出現(xiàn)這種現(xiàn)象呢？

二、各自的判定方式

慢事務(wù) 對(duì)于一個(gè)顯示提交的(insert)事務(wù)通常如下：

GTID_LOG_EVENT和XID_EVENT是命令‘COMMIT’發(fā)起的時(shí)間。
QUERY_EVENT是第一個(gè)‘Insert’命令發(fā)起的時(shí)間。
MAP_EVENT/WRITE_ROWS_EVENT是每個(gè)‘Insert’命令發(fā)起的時(shí)間。

因此我們通常通過XID_EVENT的時(shí)間減去QUERY_EVENT的時(shí)間就得到了一個(gè)慢事務(wù)時(shí)間， 當(dāng)然如果是自動(dòng)提交的則不能這么計(jì)算 ，因?yàn)楦鱾€(gè)event都是語(yǔ)句發(fā)起的時(shí)間。

commit 慢的可能性

我們知道commit慢最可能的地方在binlog的刷盤或者等待半同步從庫(kù)ACK，但是binlog中XID EVENT的時(shí)間卻不包含這部分時(shí)間，也就是說(shuō)binlog慢事務(wù)和慢查詢中的commit記錄的不是一個(gè)時(shí)間段。

簡(jiǎn)要說(shuō)明

如果我們以如下事務(wù)為例，進(jìn)行簡(jiǎn)要說(shuō)明

begin;
insert into it values(10);
commit;        
-- insert語(yǔ)句執(zhí)行      -> QUERY_EVENT時(shí)間(T1)  
-- insert語(yǔ)句執(zhí)行完成,判定insert語(yǔ)句是否為慢查詢(T2)          
-- commit語(yǔ)句執(zhí)行      -> GTID_LOG_EVENT和XID_EVENT時(shí)間(T3)
   flush
   fsync
                  -----> 傳輸binlog (sync_binlog=1)
                  <----   等待ACK   (rpl_semi_sync_master_wait_point=AFTER_SYNC)
   commit
-- commit語(yǔ)句執(zhí)行完成,判定commit語(yǔ)句是否為慢查詢(T4)

判定insert語(yǔ)句是否慢的標(biāo)準(zhǔn)是T2-T1(-鎖時(shí)間)
判定commit語(yǔ)句是否慢的標(biāo)準(zhǔn)是T4-T3
判定慢事務(wù)的標(biāo)準(zhǔn)是T3-T1

因此慢事務(wù)的判定和慢查詢中commit慢的判定幾乎沒有什么交集，因此出現(xiàn)這種情況也是正常的，下面來(lái)證明。

三、證明

主庫(kù):半同步超時(shí)時(shí)間為999999999。
從庫(kù):設(shè)置sync_relay_log=1,并且斷點(diǎn)設(shè)置在MYSQL_BIN_LOG::flush_and_sync函數(shù)上，本函數(shù)是從庫(kù)每次event寫到relay log后受到 sync_relay_log=1 的影響必須要落盤的判定函數(shù)。

這樣人為在斷點(diǎn)處等待一下就顯著的拉長(zhǎng)了commit的時(shí)間，同時(shí)也證明半同步慢會(huì)影響commit慢，如下：

begin;
select now();   -T1
insert into it values(10);
select sleep(10);
select now();   -T2
commit; (斷點(diǎn)在從庫(kù)生效卡主ack) -T3
select now();   -T4

結(jié)果
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)

我們來(lái)分析一下慢查詢和binlog，這里加入了sleep(10)拖長(zhǎng)了事務(wù)commit時(shí)間，因?yàn)閕nsert太快了。

binlog慢事務(wù) 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慢明顯不包含在慢事務(wù)中。

四、總結(jié)

基于如上我們稍微做下總結(jié)，并且加上我們常有的認(rèn)知，總結(jié)如下：

binlog慢事務(wù)中有記錄，慢查詢沒有記錄，可能事務(wù)中有大量的鎖等待信息或者是事務(wù)沒有及時(shí)提交。
慢查詢有記錄，binlog慢事務(wù)中沒有記錄，可能語(yǔ)句本身為自動(dòng)事務(wù)提交，自動(dòng)提交的事務(wù)無(wú)法計(jì)算慢事務(wù)。
如果確實(shí)是DML語(yǔ)句慢(排除加鎖時(shí)間)導(dǎo)致的慢事務(wù)并且為顯示(begin;commit)事務(wù)才會(huì)同時(shí)出現(xiàn)在binlog慢事務(wù)和慢查詢中。
慢查詢中出現(xiàn)commit慢和binlog慢事務(wù)沒有必然的關(guān)系，因?yàn)橛涗浀臅r(shí)間完全不同。
半同步慢ACK和日志刷盤慢會(huì)影響到commit慢，都會(huì)記錄到慢查詢（MGR before commit hook 處理慢也會(huì)）。
如果binlog慢事務(wù)和某些慢查詢中的select語(yǔ)句時(shí)間匹配則可能是事務(wù)中包含了select語(yǔ)句導(dǎo)致。

當(dāng)然這只是常見的總結(jié)，很多特殊原因不好說(shuō)，需要pstack等手段確認(rèn)。

到此這篇關(guān)于MySQL慢查詢中的commit慢和binlog中慢事務(wù)的差異的文章就介紹到這了,更多相關(guān)MySQL慢查詢commit和binlog慢事務(wù)內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

您可能感興趣的文章: