MySQL慢查詢中的commit慢和binlog中慢事務的區(qū)別
常見原因總結(jié)，特殊情況除外。
一、問題來源
在分析性能問題的時候慢查詢和binlog慢事務是常用的手段。最近在分析一個慢查詢的，發(fā)現(xiàn)其中包含了大量的commit語句慢，但是在分析binlog慢事務的時候不能完成匹配。比如這段時間commit的語句可能有1000個，但是慢事務可能只有100個，這個差得也太多了，那么為什么會出現(xiàn)這種現(xiàn)象呢？
二、各自的判定方式
慢事務 對于一個顯示提交的(insert)事務通常如下：
GTID_LOG_EVENT和XID_EVENT是命令‘COMMIT’發(fā)起的時間。
QUERY_EVENT是第一個‘Insert’命令發(fā)起的時間。
MAP_EVENT/WRITE_ROWS_EVENT是每個‘Insert’命令發(fā)起的時間。
因此我們通常通過XID_EVENT的時間減去QUERY_EVENT的時間就得到了一個慢事務時間， 當然如果是自動提交的則不能這么計算 ，因為各個event都是語句發(fā)起的時間。
commit 慢的可能性
我們知道commit慢最可能的地方在binlog的刷盤或者等待半同步從庫ACK，但是binlog中XID EVENT的時間卻不包含這部分時間，也就是說binlog慢事務和慢查詢中的commit記錄的不是一個時間段。
簡要說明
如果我們以如下事務為例，進行簡要說明
begin;
insert into it values(10);
commit;
-- insert語句執(zhí)行 -> QUERY_EVENT時間(T1)
-- insert語句執(zhí)行完成,判定insert語句是否為慢查詢(T2)
-- commit語句執(zhí)行 -> GTID_LOG_EVENT和XID_EVENT時間(T3)
flush
fsync
-----> 傳輸binlog (sync_binlog=1)
<---- 等待ACK (rpl_semi_sync_master_wait_point=AFTER_SYNC)
commit
-- commit語句執(zhí)行完成,判定commit語句是否為慢查詢(T4)判定insert語句是否慢的標準是T2-T1(-鎖時間)
判定commit語句是否慢的標準是T4-T3
判定慢事務的標準是T3-T1
因此慢事務的判定和慢查詢中commit慢的判定幾乎沒有什么交集，因此出現(xiàn)這種情況也是正常的，下面來證明。
三、證明
主庫:半同步超時時間為999999999。
從庫:設置sync_relay_log=1,并且斷點設置在MYSQL_BIN_LOG::flush_and_sync函數(shù)上，本函數(shù)是從庫每次event寫到relay log后受到 sync_relay_log=1 的影響必須要落盤的判定函數(shù)。
這樣人為在斷點處等待一下就顯著的拉長了commit的時間，同時也證明半同步慢會影響commit慢，如下：
begin; select now(); -T1 insert into it values(10); select sleep(10); select now(); -T2 commit; (斷點在從庫生效卡主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)
我們來分析一下慢查詢和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慢明顯不包含在慢事務中。
四、總結(jié)
基于如上我們稍微做下總結(jié)，并且加上我們常有的認知，總結(jié)如下：
binlog慢事務中有記錄，慢查詢沒有記錄，可能事務中有大量的鎖等待信息或者是事務沒有及時提交。
慢查詢有記錄，binlog慢事務中沒有記錄，可能語句本身為自動事務提交，自動提交的事務無法計算慢事務。
如果確實是DML語句慢(排除加鎖時間)導致的慢事務并且為顯示(begin;commit)事務才會同時出現(xiàn)在binlog慢事務和慢查詢中。
慢查詢中出現(xiàn)commit慢和binlog慢事務沒有必然的關(guān)系，因為記錄的時間完全不同。
半同步慢ACK和日志刷盤慢會影響到commit慢，都會記錄到慢查詢（MGR before commit hook 處理慢也會）。
如果binlog慢事務和某些慢查詢中的select語句時間匹配則可能是事務中包含了select語句導致。
當然這只是常見的總結(jié)，很多特殊原因不好說，需要pstack等手段確認。
到此這篇關(guān)于MySQL慢查詢中的commit慢和binlog中慢事務的差異的文章就介紹到這了,更多相關(guān)MySQL慢查詢commit和binlog慢事務內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！
相關(guān)文章
MySQL實現(xiàn)批量插入測試數(shù)據(jù)的方式小結(jié)
在開發(fā)過程中我們不管是用來測試性能還是在生產(chǎn)環(huán)境中頁面展示好看一點,?經(jīng)常需要一些測試數(shù)據(jù),?本文主要介紹了兩種常用的MySQL測試數(shù)據(jù)批量生成方式,希望對大家有所幫助2023-11-11
MySQL循環(huán)語句之while循環(huán)測試
MySQL有循環(huán)語句操作，while 循環(huán)、loop循環(huán)和repeat循環(huán)，目前我只測試了 while 循環(huán)，下面與大家分享下2014-07-07
ERROR 1862 (HY000): Your password has expired. To log in you
當你在安裝 MySQL過程中，通過mysqld --initialize 初始化 mysql 操作后，生成臨時密碼后，沒有直接進行 MySQL連接，中途重啟服務或者重啟機器等，導致密碼失效問題，怎么處理呢，感興趣的朋友一起看看吧2019-11-11
這篇文章主要介紹了Mysql優(yōu)化策略，文中介紹的非常詳細，對大家的學習或者工作具有一定的參考學習價值，需要的朋友們下面隨著小編來一起學習學習吧2019-04-04
這篇文章主要介紹了SQL語法CONSTRAINT約束操作詳情，CONSTRAINT，約束，即對數(shù)據(jù)庫表中的數(shù)據(jù)進行約束，以保證數(shù)據(jù)記錄的完整性和有效性。下面來看看文章的學習介紹吧2022-01-01
本文主要介紹了mysql?樂觀鎖和悲觀鎖的具體使用，文中通過示例代碼介紹的非常詳細，對大家的學習或者工作具有一定的參考學習價值，需要的朋友們下面隨著小編來一起學習學習吧2023-01-01
這篇文章主要介紹了mysql實現(xiàn)模糊查詢并按匹配程度排序方式,具有很好的參考價值,希望對大家有所幫助,如有錯誤或未考慮完全的地方,望不吝賜教2023-08-08
替換字段里數(shù)據(jù)內(nèi)容部分字符串,這個在替換網(wǎng)址呀什么的最經(jīng)常用了,發(fā)布一下做個筆記2008-06-06
MySQL的安裝卸載問題一直是一個頭疼的問題,所以想著以一篇文章來搞定這個問題,這篇文章主要給大家介紹了關(guān)于MySQL下載安裝及完美卸載的相關(guān)資料,需要的朋友可以參考下2022-08-08
關(guān)于MySQL?onlinedb數(shù)據(jù)庫的一些查詢語句大全
這篇文章主要給大家介紹了關(guān)于MySQL?onlinedb數(shù)據(jù)庫的一些查詢語句,文中通過代碼實例介紹的非常詳細,對大家學習或者使用MySQL具有一定的參考價值,需要的朋友可以參考下2023-12-12