這篇文章主要為大家展示了“binlog異常暴漲怎么回事”，內(nèi)容簡(jiǎn)而易懂，條理清晰，希望能夠幫助大家解決疑惑，下面讓小編帶領(lǐng)大家一起研究并學(xué)習(xí)一下“binlog異常暴漲怎么回事”這篇文章吧。
創(chuàng)新互聯(lián)公司是一家專注于網(wǎng)站設(shè)計(jì)、網(wǎng)站制作與策劃設(shè)計(jì),梅江網(wǎng)站建設(shè)哪家好?創(chuàng)新互聯(lián)公司做網(wǎng)站,專注于網(wǎng)站建設(shè)十載,網(wǎng)設(shè)計(jì)領(lǐng)域的專業(yè)建站公司;建站業(yè)務(wù)涵蓋:梅江等地區(qū)。梅江做網(wǎng)站價(jià)格咨詢:028-86922220
這是一個(gè)朋友遇到的問(wèn)題，他的現(xiàn)象大概如下（MySQL5.6）：
某個(gè)binlog實(shí)際大小8g左右，實(shí)際設(shè)置大小應(yīng)該是1g
其中包含一個(gè)大事務(wù)，但是最后一個(gè)事務(wù)是小事務(wù)
查看大事務(wù)的XID_EVENT（‘commit’）時(shí)間和最后一個(gè)小事務(wù)XID_EVENT（‘commit’）時(shí)間差值近15分鐘
下面是他提供的依據(jù)：
mysqlbinlog -vv mysqlbinlog_file > mysqlbinlog_res.log grep -n -B 1 "COMMIT" mysqlbinlog_res.log > file.log tar zcf file.log.tar.gz file.log 通過(guò)結(jié)果可以看到大事務(wù)提交完成是binlog文件的行號(hào)是 392578997 ，往前推一個(gè)事務(wù)， 提交完成后的行號(hào)是 42614752 ， 期間相差3.2億行，就是說(shuō)這個(gè)事務(wù)總共寫(xiě)了3.2億行的binlog 大事務(wù)提交的時(shí)間是12:54:12，Xid = 4103492840 ，結(jié)束的pos值是 2915555141 最后一個(gè)事務(wù)的提交時(shí)間13:08:43，Xid = 4104544654 ，結(jié)束的pos值是 2915740337
問(wèn)：
為什么最后事務(wù)是小事務(wù)而不是最大的那個(gè)事務(wù)，為什么大事務(wù)束后沒(méi)有切換binlog呢？
為什么最后一個(gè)小事務(wù)和大事務(wù)提交時(shí)間相差了15分鐘之多呢？
這張圖是基于MySQL5.7.22畫(huà)的：
好了有了這張圖我們繼續(xù)分析。
如圖中第10步我們可以看到在flush隊(duì)列的事務(wù)Event都寫(xiě)到binlog（不是fsync）后才會(huì)進(jìn)行binlog切換的標(biāo)記，言外之意就是不管有多大的事務(wù)那么都要等到寫(xiě)完binlog后才進(jìn)行切換標(biāo)記的設(shè)置。因此大事務(wù)總是在一個(gè)binlog里面。
事實(shí)上在第10步中我們只是設(shè)置了切換標(biāo)記而已，實(shí)際的切換會(huì)等到本事務(wù)所在的commit隊(duì)列都提交完成后才會(huì)進(jìn)行binlog的切換，具體就是參考第28步。
在這個(gè)期間會(huì)有2個(gè)原因?qū)е麓笫聞?wù)并不是binlog的最后一個(gè)事務(wù)：
對(duì)于flush隊(duì)列而言，大事務(wù)可能包含在隊(duì)列中的某個(gè)位置，隊(duì)列后面可能包含小事務(wù)。
對(duì)于sync隊(duì)列而言，大事務(wù)的提交會(huì)在sync階段耗費(fèi)很多時(shí)間，如果我們假設(shè)為30秒，那么在這30秒內(nèi)其他新的事務(wù)是可以進(jìn)入新的flush隊(duì)列的，也能夠進(jìn)行寫(xiě)binlog（不是fsync）的操作。
因此線上有壓力的庫(kù)，binlog的最后一個(gè)事務(wù)通常不是大事務(wù)。
首先這個(gè)問(wèn)題有兩種可能：
對(duì)于自動(dòng)事務(wù)提交，那么XID_EVENT會(huì)是命令發(fā)起的時(shí)間，因此更容易出現(xiàn)這種情況，后面會(huì)使用這種情況進(jìn)行證明。
對(duì)于顯示開(kāi)啟事務(wù)‘begin commit’，那么XID_EVENT會(huì)是commit命令發(fā)起的時(shí)間，但是如果fsync時(shí)間足夠久那么也會(huì)出現(xiàn)這種問(wèn)題。這種情況不容易測(cè)試，因?yàn)樾枰銐虼蟮臄?shù)據(jù)，人為測(cè)試很耗時(shí)。下面就是這種情況出現(xiàn)的原因。
關(guān)于以上兩種情況的這種差別我已經(jīng)在我的《深入理解MySQL主從原理 32講》中第12講、第14講說(shuō)明了原因。
這里我們就假定大事務(wù)的提交在sync階段花費(fèi)了大約15分鐘，那么如下：
| 大事務(wù)flush | T1 | ||
| 大事務(wù)sync開(kāi)始 | T2 | 小事務(wù)flush | T2 |
| 小事務(wù)flush | T3 | ||
| 小事務(wù)flush | T4 | ||
| 大事務(wù)sync結(jié)束 | T5 |
如果T5和T2之間相差15分鐘左右，那么這期間進(jìn)來(lái)的這些小事務(wù)依然保留在本binlog里面（因?yàn)檫€沒(méi)切換29步才切換），那么就有可能看到小事務(wù)和大事務(wù)之間XID_EVENT（commit）時(shí)間相差很大了。
實(shí)際上在5.7中上面兩種情況都很可能都會(huì)生成同樣的last commit，因?yàn)檫@個(gè)時(shí)候由于大事務(wù)fsync的堵塞第22步更改last commit的操作是不能進(jìn)行的。
整個(gè)測(cè)試過(guò)程必須卡準(zhǔn)大事務(wù)進(jìn)行提交這個(gè)時(shí)間點(diǎn)，我的參數(shù)設(shè)置如下：
max_binlog_size：1048576，設(shè)置較小的binlog大小方便測(cè)試。
binlog_group_commit_sync_delay：1000000，將本參數(shù)設(shè)置為1秒，用于拖長(zhǎng)整個(gè)提交流程便于測(cè)試，但是實(shí)際上大事務(wù)的fsync操作可能會(huì)更加耗時(shí)。
binlog_transaction_dependency_tracking：COMMIT_ORDER，這是默認(rèn)的配置，為了更好的證明我們前面生成同樣的last commit的結(jié)論，避免writeset的干擾。
并且我在我的debug環(huán)境中設(shè)置了斷點(diǎn)MYSQL_BIN_LOG::ordered_commit，用于更好的測(cè)試，否則自動(dòng)提交事務(wù)的情況下非常難確認(rèn)事務(wù)到底什么時(shí)候進(jìn)行提交的。
最后我們不使用通過(guò)‘begin commit’顯示的開(kāi)啟事務(wù)，因?yàn)檫@樣X(jué)ID_EVENT的時(shí)間是commit命令發(fā)起的時(shí)間，也就不太容易重現(xiàn)案例中的這種XID_EVENT大事務(wù)和小事務(wù)時(shí)間相差很大現(xiàn)象。但是實(shí)際上如果事務(wù)足夠大也是可以的，因?yàn)樵诖笫聞?wù)如案例中有幾億的數(shù)據(jù)那么這個(gè)事務(wù)的sync過(guò)程會(huì)非常緩慢，但是我的測(cè)試環(huán)境沒(méi)有那么多的數(shù)據(jù)，為了讓測(cè)試效果更加明顯因此使用自動(dòng)提交，這樣所有的Event都是命令發(fā)起的時(shí)間。
首先我做了一張較大的表有70W的數(shù)據(jù)，然后刪除整個(gè)表的數(shù)據(jù)，顯然這個(gè)事務(wù)的binlog會(huì)大于1M。下面這個(gè)表格就是操作流程：
| T1：delete from testnnn;（70W行數(shù)據(jù)） | ||
| T2：進(jìn)入提交流程斷點(diǎn)觸發(fā) | ||
| T3：delete from tm10;（1行數(shù)據(jù)） | ||
| T4：delete from tmpk;（1行數(shù)據(jù)） | ||
| T5：所有事務(wù)提交完成 |
只要T4-T1的時(shí)間足夠長(zhǎng)那么就可能出現(xiàn)案例中的情況。如下是我的binlog的截圖，可以看到binlog.000017為3.5M左右：
下面是我解析binlog.000017的最后部分內(nèi)容，我們可以發(fā)現(xiàn)最后兩個(gè)事務(wù)均是小事務(wù)，大事務(wù)并不是最后一個(gè)事務(wù)如下：
### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ ### DELETE FROM `testmts`.`testnnn` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ # at 3626617 #190804 22:56:10 server id 413340 end_log_pos 3626648 CRC32 0xfc5b79e7 Xid = 143 COMMIT/*!*/; # at 3626648 #190804 23:02:26 server id 413340 end_log_pos 3626713 CRC32 0xa2399157 GTID last_committed=0 sequence_number=2 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'cb7ea36e-670f-11e9-b483-5254008138e4:191'/*!*/; # at 3626713 #190804 23:02:26 server id 413340 end_log_pos 3626788 CRC32 0x555fb49d Query thread_id=4 exec_time=0 error_code=0 SET TIMESTAMP=1564930946/*!*/; BEGIN /*!*/; # at 3626788 #190804 23:02:26 server id 413340 end_log_pos 3626838 CRC32 0xec0a4316 Table_map: `testmts`.`tm10` mapped to number 149 # at 3626838 #190804 23:02:26 server id 413340 end_log_pos 3626878 CRC32 0x61c79d68 Delete_rows: table id 149 flags: STMT_END_F ### DELETE FROM `testmts`.`tm10` ### WHERE ### @1=10 /* INT meta=0 nullable=1 is_null=0 */ # at 3626878 #190804 23:02:26 server id 413340 end_log_pos 3626909 CRC32 0x2a9cd136 Xid = 154 COMMIT/*!*/; # at 3626909 #190804 23:02:26 server id 413340 end_log_pos 3626974 CRC32 0x06b081ec GTID last_committed=0 sequence_number=3 rbr_only=yes /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= 'cb7ea36e-670f-11e9-b483-5254008138e4:192'/*!*/; # at 3626974 #190804 23:02:26 server id 413340 end_log_pos 3627049 CRC32 0x0e214995 Query thread_id=5 exec_time=1 error_code=0 SET TIMESTAMP=1564930946/*!*/; BEGIN /*!*/; # at 3627049 #190804 23:02:26 server id 413340 end_log_pos 3627104 CRC32 0x8ee0af93 Table_map: `testmts`.`tmpk` mapped to number 150 # at 3627104 #190804 23:02:26 server id 413340 end_log_pos 3627154 CRC32 0x4804be49 Delete_rows: table id 150 flags: STMT_END_F ### DELETE FROM `testmts`.`tmpk` ### WHERE ### @1=1 /* INT meta=0 nullable=0 is_null=0 */ ### @2='g' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */ ### @3=1 /* INT meta=0 nullable=1 is_null=0 */ ### @4=1 /* INT meta=0 nullable=1 is_null=0 */ # at 3627154 #190804 23:02:26 server id 413340 end_log_pos 3627185 CRC32 0x64f2ea15 Xid = 153 COMMIT/*!*/;
仔細(xì)觀察你會(huì)發(fā)現(xiàn) 23:02:26和22:56:10之間相差了6分鐘之多。然后我們來(lái)看看他們的last commit如下：
[root@mysqltest2 log]# cat -n log.log|grep last 11 #190804 22:56:10 server id 413340 end_log_pos 299 CRC32 0x47602f13 GTID last_committed=0 sequence_number=1 rbr_only=yes 2167349 #190804 23:02:26 server id 413340 end_log_pos 3626713 CRC32 0xa2399157 GTID last_committed=0 sequence_number=2 rbr_only=yes 2167368 #190804 23:02:26 server id 413340 end_log_pos 3626974 CRC32 0x06b081ec GTID last_committed=0 sequence_number=3 rbr_only=yes
我們發(fā)現(xiàn)如我們所述，它們的last commit是一致的。到這里我們?nèi)康慕Y(jié)論都得到證明。
以上是“binlog異常暴漲怎么回事”這篇文章的所有內(nèi)容，感謝各位的閱讀！相信大家都有了一定的了解，希望分享的內(nèi)容對(duì)大家有所幫助，如果還想學(xué)習(xí)更多知識(shí)，歡迎關(guān)注創(chuàng)新互聯(lián)行業(yè)資訊頻道！
重慶分公司
重慶分公司
