1.場景描述
早上7：25 接到Report中心同學告警，昨天業務報表資料沒有完整跑出來，缺少500位業務員的資料，并且很快定位到，缺少的是huabei_order庫上的資料，Report中心的資料是BI每天5:15從huabei_order庫的從庫上抽取，查看監控告警，從庫實體確實在4:50 --6:00 有延遲，但已恢復，報表資料不完整，直接原因就是主從延遲，
7:50 確認主從延遲已恢復，請求BI重新抽取資料，重新生成報表，
8：20 報表資料驗證無誤，
問題還沒結束：
忽略監控告警的不及時、不完整，
還需要回答的問題是為什么在業務低峰期會出現延遲？是什么操作造成的？【問題1】
監控界面主從延遲指標
看到這樣的走勢圖，又一個需要思考的問題:為什么延遲會瞬間飆升到24440s以上（實際可能已達25K以上），延遲不應該是逐漸累積的嗎？【問題2】
確實是業務低峰期，和研發、產品、業務確認，23:30 之后沒有大的操作、大的流量，也沒有特別的活動、促銷，從資料庫Server業務壓力上考慮，確實沒有特殊的操作，
忽然想到，備份，完整備份，我們的災備，資料庫的完整備份實在從庫上做的，cron 設定在每天的00:05 , 一般執行2個小時， 并且是周二、周五執行，當天正好是周二，
雖然自己也不太相信這個就是真正的原因，但畢竟是一個可考慮的因素，查看完整備份的log，
2.全量備份
失敗
報錯資訊如下:
210831 04:49:46 >> log scanned up to (1168680308582) 210831 04:49:47 >> log scanned up to (1168680308668) 210831 04:49:48 >> log scanned up to (1168680308770) 210831 04:49:49 >> log scanned up to (1168680308856) 210831 04:49:50 >> log scanned up to (1168680308942) 210831 04:49:51 >> log scanned up to (1168680309028) 210831 04:49:52 >> log scanned up to (1168680309114) InnoDB: Last flushed lsn: 1168515708469 load_index lsn 1168680309114 InnoDB: An optimized (without redo logging) DDLoperation has been performed. All modified pages may not have been flushed to the disk yet. PXB will not be able take a consistent backup. Retry the backup operation mysql: [Warning] Using a password on the command line interface can be insecure.
失敗了，并且時間都很吻合，04:49 完整備份失敗，04:49 主從延遲瞬間飆升，
查看完整備份歷史，過去備份耗時在2個小時左右，而本次備份執行了4個小時50分鐘，還失敗了，
（說明:從完整備份列印的log來看，列印FLUSH TABLES WITH READ LOCK時，完整備份就快結束了，所以，在此圖上，通過FLUSH TABLES WITH READ LOCK的時間代表完整備份結束的時間）
到此時，相信很多同學，已經準備把鍋甩給完整備份了，
需要思考的問題 :DDL操作和xtrabackup是怎么相互影響的？為什么全量備份失敗后，延遲問題才會馬上被監控到（Seconds_Behind_Master才顯示例外）？【問題3】
3.繼續分析原因，尋找DDL
每個問題都不簡單，
我們先看問題3.DDL操作和xtrabackup是怎么相互影響的？為什么全量備份失敗后，延遲問題才會馬上被監控到（Seconds_Behind_Master才顯示例外）？【問題3】
回答這個問題，需要先找到具體的DDL操作，
但是備份期間沒有執行過DDL操作，上次一DDL操作 要追溯到前一天19:50，迷霧重重、元兇隱隱，
想到MySQL DDL操作，一般執行時間相對較長，slow log 中或許有蛛絲馬跡，
ELK--MySQL日志系統走起，
還是找到了一條大魚，alter table ,添加欄位，時間點吻合（04:49）,執行時間超長25438秒（并且和Seconds_Behind_Master飆升后的值很接近 ），
從庫DDL執行log
25438秒 ≈ 7 小時
從庫所有的操作都來自主庫，接下來，我們看下主庫啥時候執行DDL的，
主庫DDL執行情況
主庫執行了 5089 秒，結束于 前一天的21：18，向前推 5089 秒，也就是 19:50前后，
為什么執行時間會這么長呢？這張表確實是大表、寬表--1.6 億 資料量、130G大小，其資訊如下:
所以，到現在，才算把主從延遲的問題定位到-----DDL 和 innobackupex，兩者相互影響、相互拖累，才導致這個時間段內的延遲產生，這也算問題1的答案吧，
4.Seconds_Behind_Master 問題解答
此處我們嘗試問答第二個問題:為什么延遲,會瞬間飆升到24440S以上，延遲不應該是逐漸累積的嗎？【問題2】
我么先看下主從復制指標:Seconds_Behind_Master 的官方描述
Seconds_Behind_Master: The number of seconds that the replication SQL thread is behind processing the source's binary log. A high number (or an increasing one) can indicate that the replica is unable to handle events from the source in a timely fashion.
A value of 0 for Seconds_Behind_Master can usually be interpreted as meaning that the replica has caught up with the source, but there are some cases where this is not strictly true. For example, this can occur if the network connection between source and replica is broken but the replication I/O thread has not yet noticed this—that is, slave_net_timeout has not yet elapsed.
It is also possible that transient values for Seconds_Behind_Master may not reflect the situation accurately. When the replication SQL thread has caught up on I/O, Seconds_Behind_Master displays 0; but when the replication I/O thread is still queuing up a new event, Seconds_Behind_Master may show a large value until the SQL thread finishes executing the new event. This is especially likely when the events have old timestamps; in such cases, if you execute SHOW SLAVE STATUS several times in a relatively short period, you may see this value change back and forth repeatedly between 0 and a relatively large value.
Check the Seconds_Behind_Master column in the output from SHOW REPLICA | SLAVE STATUS.
When the replication SQL thread executes an event read from the source, it modifies its own time to the event timestamp. (This is why TIMESTAMP is well replicated.) In the Time column in the output of SHOW PROCESSLIST, the number of seconds displayed for the replication SQL thread is the number of seconds between the timestamp of the last replicated event and the real time of the replica machine. You can use this to determine the date of the last replicated event. Note that if your replica has been disconnected from the source for one hour, and then reconnects, you may immediately see large Time values such as 3600 for the replication SQL thread in SHOW PROCESSLIST. This is because the replica is executing statements that are one hour old.
通過以上的描述 和 本 Case 中 Seconds_Behind_Master 的數字變化：
Seconds_Behind_Master 似乎應該為:SQL thread 重做主節點同步過來的binlog even, 執行提交后，比較從節點執行even的時間和主節點binlog event 中的時間所得到時間差，
再回答這個問題， Seconds_Behind_Master瞬間飆升到24440S 以上【因為我們的telegraf 抓取是20S一次，并且從監控庫圖上可看到，有一個快速下降趨勢，所以，真正的最大值應該為25K以上，很可能會比慢查詢的25438 還稍微大些】，這個值是怎么來的？應該就是從庫DDL提交的時刻【04：49】減去主庫DDL提交的時刻【前一天的21:18】的差值， --這也算問題2的答案吧，
所以，Seconds_Behind_Master = 0 時，主從延遲可能已經很厲害了，除了官網提到的網路問題，還有就是從庫正則執行同步過來的大DDL（尚未提交），例如在本例的00:00---04:00 其實已經存在延遲了，
5.innobackupex知識補充
關于問題 3中 為什么全量備份失敗后，延遲問題才會馬上被監控到（Seconds_Behind_Master才顯示例外）？ 目前來看，尚未分析到直接因果關系，應該是概率事件，
innobackupex備份流程圖如下：
經過驗證測驗，innobackupex備份開始時，并不是先看當前資料庫是否有DDL操作，而是其中的某個執行緒在備份這張表時（或 scan lsn）才判斷是否有DDL，有則推出報錯，驗證方法，在一張大表上執行DDL（保證DDL時間足夠長），在DDL運行期間，開始備份，我們我看到這個很多表在執行copy備份，是運行了一段時間后，才報錯的，
此外， innobackupex備份程序中，執行DDL，都會導致備份失敗，與表大小無關，即使這張表只有一筆資料，
補充說明：
MySQL版本為5.7.22
innobackupex的版本為 innobackupex version 2.4.9 Linux (x86_64) (revision id: a467167cdd4)
6.參考文獻
1.mysqldump與innobackupex備份程序知多少（完結篇）
https://blog.csdn.net/joy0921/article/details/80130860
2.MySQL中的seconds_behind_master的理解
https://www.cnblogs.com/drizzle-xu/p/9713350.html?ivk_sa=1024320u
3.How do I know how late a replica is compared to the source?
https://dev.mysql.com/doc/refman/8.0/en/faqs-replication.html
轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/297060.html
標籤：其他
上一篇：TDSQL-A與CK的對比