一、前言
最近公司某項目上反饋MySQL主從復制失敗，被運維部門記了一次大過，影響到了項目的驗收推進，那么究竟是什么原因導致的呢？而主從復制的原理又是什么呢？本文就對排查分析的過程做一個記錄。
二、主從復制原理
我們先來簡單了解下MySQL主從復制的原理。
1.主庫master 服務器會將 SQL 記錄通過 dump 線程寫入到二進制日志binary log中。
2.從庫slave 服務器開啟一個 io thread 線程向服務器發送請求，向 主庫master 請求 binary log。主庫master 服務器在接收到請求之后，根據偏移量將新的 binary log 發送給 slave 服務器。
3.從庫slave 服務器收到新的 binary log 之后，寫入到自身的 relay log 中，這就是所謂的中繼日志。
4.從庫slave 服務器，單獨開啟一個 sql thread 讀取 relay log 之后，寫入到自身數據中，從而保證主從的數據一致。
以上是MySQL主從復制的簡要原理，更多細節不展開討論了，根據運維反饋，主從復制失敗主要在IO線程獲取二進制日志binlog超時，一看主數據庫的binlog日志竟達到了4個G，正常情況下根據配置應該是不超過300M。
三、binlog寫入機制
想要了解binlog為什么達到4個G，我們來看下binlog的寫入機制。
binlog的寫入時機也非常簡單，事務執行過程中，先把日志寫到 binlog cache ，事務提交的時候，再把binlog cache寫到binlog文件中。因為一個事務的binlog不能被拆開，無論這個事務多大，也要確保一次性寫入，所以系統會給每個線程分配一個塊內存作為binlog cache。
- 上圖的write，是指把日志寫入到文件系統的page cache，并沒有把數據持久化到磁盤，所以速度比較快
- 上圖的fsync，才是將數據持久化到磁盤的操作, 生成binlog日志中
生產上MySQL中binlog中的配置max_binlog_size為250M, 而max_binlog_size是用來控制單個二進制日志大小，當前日志文件大小超過此變量時，執行切換動作。,該設置并不能嚴格控制Binlog的大小，尤其是binlog比較靠近最大值而又遇到一個比較大事務時，為了保證事務的完整性，可能不做切換日志的動作，只能將該事務的所有$QL都記錄進當前日志，直到事務結束。一般情況下可采取默認值。
所以說懷疑是不是遇到了大事務，因而我們需要看看binlog中的內容具體是哪個事務導致的。
四、查看binlog日志
我們可以使用mysqlbinlog這個工具來查看下binlog中的內容，具體用法參考官網：https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html。
1.查看binlog日志
./mysqlbinlog --no-defaults ---output=decode-rows -vv /mysqldata/mysql/binlog/mysql-bin.004816|more
2.以事務為單位統計binlog日志文件中占用的字節大小
./mysqlbinlog --no-defaults ---output=decode-rows -vv /mysqldata/mysql/binlog/mysql-bin.004816|grep GTID -B1|grep '^# at' | awk '{print $3}' | awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp, tmp, $1); tmp=$1}'|sort -n -r|more
生產中某個事務竟然占用4個G。
3.通過start-position和stop-position統計這個事務各個SQL占用字節大小
./mysqlbinlog --no-defaults ---output=decode-rows --start-position='xxxx' --stop-position='xxxxx' -vv /mysqldata/mysql/binlog/mysql-bin.004816 |grep '^# at'| awk '{print $3}' | awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp, tmp, $1); tmp=$1}'|sort -n -r|more
發現最大的一個SQL竟然占用了32M的大小，那超過10M的大概有多少個呢？
4.通過超過10M大小的數量
./mysqlbinlog --no-defaults ---output=decode-rows --start-position='xxxx' --stop-position='xxxxx' -vv /mysqldata/mysql/binlog/mysql-bin.004816|grep '^# at' | awk '{print $3}' | awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp, tmp, $1); tmp=$1}'|awk '$1>10000000 {print $0}'|wc -l
統計結果顯示竟然有200多個，毛估一下，也有近4個G了.
5.根據pos, 我們看下究竟是什么SQL導致的
./mysqlbinlog --no-defaults ---output=decode-rows --start-position='xxxx' --stop-position='xxxxx' -vv /mysqldata/mysql/binlog/mysql-bin.004816|grep '^# atxxxx' -C5| grep -v '###' | more
根據sql，分析了下，這個表正好有個blob字段，統計了下blob字段總合大概有3個G大小，然后我們業務上有個導入操作，這是一個非常大的事務，會頻繁更新這表中記錄的更新時間，導致生成binlog非常大。
問題： 明明只是簡單的修改更新時間的語句，壓根沒有動blob字段，為什么生產的binlog這么大？因為生產的binlog采用的是row模式。
五、binlog的模式
binlog日志記錄存在3種模式，而生產使用的是row模式，它最大的特點，是很精確，你更新表中某行的任何一個字段，會記錄下整行的內容，這也就是為什么blob字段都被記錄到binlog中，導致binlog非常大。此外，binlog還有statement和mixed兩種模式。
1.STATEMENT模式 ，基于SQL語句的復制
- 優點：不需要記錄每一行數據的變化，減少binlog日志量，節約IO，提高性能。
- 缺點：由于只記錄語句，所以，在statement level下 已經發現了有不少情況會造成MySQL的復制出現問題，主要是修改數據的時候使用了某些定的函數或者功能的時候會出現。
2.ROW模式，基于行的復制
5.1.5版本的MySQL才開始支持，不記錄每條sql語句的上下文信息，僅記錄哪條數據被修改了，修改成什么樣了。
- 優點：binlog中可以不記錄執行的sql語句的上下文相關的信息，僅僅只需要記錄那一條被修改。所以rowlevel的日志內容會非常清楚的記錄下每一行數據修改的細節。不會出現某些特定的情況下的存儲過程或function，以及trigger的調用和觸發無法被正確復制的問題。
- 缺點：所有的執行的語句當記錄到日志中的時候，都將以每行記錄的修改來記錄，會產生大量的日志內容。
3.MIXED模式
從5.1.8版本開始，MySQL提供了Mixed格式，實際上就是Statement與Row的結合。
在Mixed模式下，一般的語句修改使用statment格式保存binlog。如一些函數，statement無法完成主從復制的操作，則采用row格式保存binlog。
六、總結
最終分析下來，我們定位到原來是由于大事務+blob字段大致binlog非常大，最終我們采用了修改業務代碼，將blob字段單獨拆到一張表中解決。所以，在設計開發過程中，要盡量避免大事務，同時在數據庫建模的時候特別考慮將blob字段獨立成表。
作者丨JAVA旭陽
來源丨公眾號：JAVA旭陽（ID：javaxuxukkkk）
dbaplus社群歡迎廣大技術人員投稿，投稿郵箱：editor@dbaplus.cn
關于我們
dbaplus社群是圍繞Database、BigData、AIOps的企業級專業社群。資深大咖、技術干貨，每天精品原創文章推送，每周線上技術分享，每月線下技術沙龍，每季度Gdevops&DAMS行業大會。
