binlog 異常暴漲分析
這是一個朋友遇到的問題，他的現象大概如下（MySQL5.6）：
- 某個binlog實際大小8g左右，實際設定大小應該是1g
- 其中包含一個大事務，但是最後一個事務是小事務
- 檢視大事務的XID_EVENT（‘commit’）時間和最後一個小事務XID_EVENT（‘commit’）時間差值近15分鐘
下面是他提供的依據：
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
通過結果可以看到大事務提交完成是binlog檔案的行號是 392578997 ，往前推一個事務，
提交完成後的行號是 42614752 ，
期間相差3.2億行，就是說這個事務總共寫了3.2億行的binlog
大事務提交的時間是12:54:12，Xid = 4103492840 ，結束的pos值是 2915555141
最後一個事務的提交時間13:08:43，Xid = 4104544654 ，結束的pos值是 2915740337
問：
- 為什麼最後事務是小事務而不是最大的那個事務，為什麼大事務束後沒有切換binlog呢？
- 為什麼最後一個小事務和大事務提交時間相差了15分鐘之多呢？
實際上這些問題的原因我都在我的《深入理解MySQL主從原理 32講》中說明了，有興趣可以關注一下：
好了下面我們來實際分析一下。
一、提交流程圖
這張圖是《深入理解MySQL主從原理 32講》中第15節的擷取如下，當然這個圖是基於MySQL5.7.22畫的：
好了有了這張圖我們繼續分析。
二、為什麼大事務會包含在一個binlog裡面
如圖中第10步我們可以看到在flush佇列的事務Event都寫到binlog（不是fsync）後才會進行binlog切換的標記，言外之意就是不管有多大的事務那麼都要等到寫完binlog後才進行切換標記的設定。因此大事務總是在一個binlog裡面。
三、為什麼最後事務是小事務而不是最大的那個事務
事實上在第10步中我們只是設定了切換標記而已，實際的切換會等到本事務所在的commit佇列都提交完成後才會進行binlog的切換，具體就是參考第28步。
在這個期間會有2個原因導致大事務並不是binlog的最後一個事務：
-
對於flush佇列而言，大事務可能包含在佇列中的某個位置，佇列後面可能包含小事務。
-
對於sync佇列而言，大事務的提交會在sync階段耗費很多時間，如果我們假設為30秒，那麼在這30秒內其他新的事務是可以進入新的flush佇列的，也能夠進行寫binlog（不是fsync）的操作。
因此線上有壓力的庫，binlog的最後一個事務通常不是大事務。
四、為什麼最後一個小事務和大事務之間XID_EVENT（commit）時間相差了15分鐘之多呢？
首先這個問題有兩種可能：
-
對於自動事務提交，那麼XID_EVENT會是命令發起的時間，因此更容易出現這種情況，後面會使用這種情況進行證明。
-
對於顯示開啟事務‘begin commit’，那麼XID_EVENT會是commit命令發起的時間，但是如果fsync時間足夠久那麼也會出現這種問題。這種情況不容易測試，因為需要足夠大的資料，人為測試很耗時。下面就是這種情況出現的原因。
關於以上兩種情況的這種差別我已經在我的《深入理解MySQL主從原理 32講》中第12講、第14講說明了原因。
這裡我們就假定大事務的提交在sync階段花費了大約15分鐘，那麼如下：
| 大事務flush | T1 | ||
| 大事務sync開始 | T2 | 小事務flush | T2 |
| 小事務flush | T3 | ||
| 小事務flush | T4 | ||
| 大事務sync結束 | T5 |
如果T5和T2之間相差15分鐘左右，那麼這期間進來的這些小事務依然保留在本binlog裡面（因為還沒切換29步才切換），那麼就有可能看到小事務和大事務之間XID_EVENT（commit）時間相差很大了。
實際上在5.7中上面兩種情況都很可能都會生成同樣的last commit，因為這個時候由於大事務fsync的堵塞第22步更改last commit的操作是不能進行的。
五、在5.7.22中測試
整個測試過程必須卡準大事務進行提交這個時間點，我的引數設定如下：
- max_binlog_size：1048576，設定較小的binlog大小方便測試。
- binlog_group_commit_sync_delay：1000000，將本引數設定為1秒，用於拖長整個提交流程便於測試，但是實際上大事務的fsync操作可能會更加耗時。
- binlog_transaction_dependency_tracking：COMMIT_ORDER，這是預設的配置，為了更好的證明我們前面生成同樣的last commit的結論，避免writeset的干擾。
並且我在我的debug環境中設定了斷點MYSQL_BIN_LOG::ordered_commit，用於更好的測試，否則自動提交事務的情況下非常難確認事務到底什麼時候進行提交的。
最後我們不使用通過‘begin commit’顯示的開啟事務，因為這樣XID_EVENT的時間是commit命令發起的時間，也就不太容易重現案例中的這種XID_EVENT大事務和小事務時間相差很大現象。但是實際上如果事務足夠大也是可以的，因為在大事務如案例中有幾億的資料那麼這個事務的sync過程會非常緩慢，但是我的測試環境沒有那麼多的資料，為了讓測試效果更加明顯因此使用自動提交，這樣所有的Event都是命令發起的時間。
首先我做了一張較大的表有70W的資料，然後刪除整個表的資料，顯然這個事務的binlog會大於1M。下面這個表格就是操作流程：
| T1：delete from testnnn;（70W行資料） | ||
| T2：進入提交流程斷點觸發 | ||
| T3：delete from tm10;（1行資料） | ||
| T4：delete from tmpk;（1行資料） | ||
| T5：所有事務提交完成 |
只要T4-T1的時間足夠長那麼就可能出現案例中的情況。如下是我的binlog的截圖，可以看到binlog.000017為3.5M左右：
下面是我解析binlog.000017的最後部分內容，我們可以發現最後兩個事務均是小事務，大事務並不是最後一個事務如下：
### 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/*!*/;
仔細觀察你會發現 23:02:26和22:56:10之間相差了6分鐘之多。然後我們來看看他們的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
我們發現如我們所述，它們的last commit是一致的。到這裡我們全部的結論都得到證明。
六、注意
最後需要提醒一下，MySQL不要有過大的事務，我覺得大事務最大的危害在於會堵塞整個資料庫其他事務的提交，這個在我的《深入理解MySQL主從原理 32講》中已經多次提到，這裡就不在贅述了。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/7728585/viewspace-2652664/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- Flutter 常見異常分析Flutter
- 手動註冊binlog檔案造成主從異常
- Android異常分析(轉)Android
- 記一次 .NET 某電力系統 記憶體暴漲分析記憶體
- 記一次 .NET 某餐飲小程式 記憶體暴漲分析記憶體
- 記一次 .NET 某外貿ERP 記憶體暴漲分析記憶體
- 伺服器負載暴漲以後…伺服器負載
- MySQL：MGR修改max_binlog_cache_size引數導致異常MySql
- 跑批SQL效能異常分析SQL
- MySql Binlog 說明 & Canal 整合MySql的更新異常說明 & MySql Binlog 常用命令彙總MySql
- windbg分析一次大查詢導致的記憶體暴漲記憶體
- 記一次 .NET醫療布草API程式 記憶體暴漲分析API記憶體
- 記一次 .NET某裝潢ERP系統 記憶體暴漲分析記憶體
- wireshark、異常資料分析、常見RST介紹
- consistent gets暴漲的一種情況
- 當機導致slave異常分析
- Oracle JOB異常中斷原因分析Oracle
- RIT為何暴漲52%？難道就是個偶然！？
- 10款人氣暴漲的PHP開源工具PHP開源工具
- 急求板大哥，Tomcat記憶體暴漲Tomcat記憶體
- 異常篇——異常處理
- [異常等待事件latch undo global data]分析事件
- RocketMQ Series---No route info of this topic異常分析MQ
- 一次VPN隧道建立異常分析
- Java異常的深入研究與分析Java
- DRF之異常捕獲原始碼分析原始碼
- 記一次 .NET 某WMS倉儲打單系統 記憶體暴漲分析記憶體
- 網際網路+刺激醫藥股暴漲 漲幅前十均超100%
- Linux 常見異常分析，請收好這份排查指南~Linux
- Java 異常（二） 自定義異常Java
- Java checked異常和unchecked異常。Java
- OGG相關的CPATURE導致SYSAUX表空間異常暴增處理UX
- Java 8 腰斬！Java 17 暴漲 2300%！！Java
- CTA：2016年智慧穿戴銷量或暴漲
- 比特幣突然炸裂：暴漲22％逼近500美刀！比特幣
- JAVA異常處理原則和log4j輸出詳細異常分析Java
- 記一次 .NET 某三甲醫院HIS系統 記憶體暴漲分析記憶體
- 異常-編譯期異常和執行期異常的區別編譯