作者：徐文梁
愛可生DBA成員，負責客戶項目的需求和維護。目前在數據庫新手村打怪升級中。喜歡垂釣，如果你也喜歡垂釣，可以約個晴好天氣，咱們一邊釣魚一邊聊聊數據庫，豈不快哉。
本文來源：原創投稿
* 愛可生開源社區出品，原創內容未經授權不得隨意使用，轉載請聯系小編并注明來源。
問題現象
某天早上，正在搬磚，客戶發來消息，反饋某個實例主從延時值反復在一萬多到0之間來回跳動，如下:
手動執行show slave statusG命令查看Seconds_Behind_Master延時值，結果如下：
問題定位
接到問題，作為一個認真工作的我，立馬行動起來。首先確認了下客戶的數據庫版本，客戶反饋是5.7.31，緊接著找客戶確認了下復制方式，如下圖:
客戶現場的slave_parallel_type值為DATABASE,slave_parallel_workers值為0，此時主從同步使用的是單SQL線程方式，在遇到大事務時產生延遲的可能性更大。推薦客戶換成MTS方式，但是客戶反饋之前一直使用的是該種方式，之前未發生此種現象，需要排查原因。
于是和客戶確認異常期間是否有業務變動，客戶反饋發生問題之前有新業務上線，qps相對平時大很多，同時存在大量insert和update批量寫操作，另外，客戶服務器使用的云服務器，配置不高。出現問題后，新業務已經臨時下線。
了解背景后，就有了排查的方向了。從根源進行分析，second-behind-master值與三個值有關，1.當前從服務器的系統時間。2.從庫服務器和主庫服務器的系統時間的差值。3.mi->last_timestamp。
對于單線程模式下的dml操作，記錄在binlog中，query_event 的ev->exec_time基本為0，可以忽略，因為query_event的exec_time只記錄第一條數據更改消耗的時間，且我們一般看到是begin。所以last_master_timestamp就基本等于各個event中header的timestamp。一個事務中，GTID_EVENT和XID_EVENT中記錄的是提交時刻的時間，而對于其他event都是命令發起時刻的時間，此時second-behind-master的計算方式為從庫服務器時間-各個event中header中time stamp的時間-主從服務器時間差，因此如果存在長時間未提交的事務或者存在大事務在SQL線程應用的時候可能會觀察到seconds_behind_master的瞬間跳動。
由于目前新業務已經下線，業務量已經漸漸恢復到正常狀態，故暫未做其他處理，建議客戶觀察一段時間，一段時間后客戶反饋恢復正常，到此，問題解決了。
問題思考
問題解決了，但是愛琢磨的我卻陷入了思考。腦海中浮現出幾個問題，第一，怎樣盡可能避免這種現象？第二，怎么確定是否有長時間未提交的事務和大事務呢？第三，發現這種問題如何挽救呢?
其實從事務發展歷程來看，這三個問題也恰恰對應著問題處理過程中的預防，診治，治療三個階段。
對于預防，即第一個問題，可以從以下幾個點出發:1.生產環境條件允許的情況下建議開啟并行復制。2.在業務上線前進行業務量評估和SQL審核，避免某些不規范SQL或業務邏輯導致出現上述問題。
對于排查，即第二個問題，排查長時間未提交的事務或者大事務可以通過show processlist命令或查看information_schema.innodb_trx表進行排查，但是這個只能查詢當前的事務，對于歷史的則無法進行查找，此時可以通過MySQLbinlog或者my2sql工具解析binlog日志，但是結果往往不直觀，咨詢了一些前輩，推薦了一款infobin工具，自己測試了下還是挺好用的，使用示例:
執行命令 infobin mysql-bin.000005 20 2000000 10 -t >/root/result.log
其中，mysql-bin.000005表示需要解析的binlog文件名，20表示是分片數量,將binlog分為大小相等的片段，生成時間越短則這段時間生成binlog量越大，則事務越頻繁，2000000表示將大于2M左右的事物定義為大事務，10表示將大于10秒未提交的事物定義為長期未提交的事務，-t 表示不做詳細event解析輸出，僅僅獲取相應的結果。
輸出結果如下:
#表示是小端平臺
Check is Little_endian
[Author]: gaopeng [QQ]:22389860 [blog]:http://blog.itpub.NET/7728585/
Warning: This tool only Little_endian platform!
Little_endian check ok!!!
-------------Now begin--------------
#MySQL的版本
Check Mysql Version is:5.7.25-log
#binlog格式版本
Check Mysql binlog format ver is:V4
#binlog不在寫入
Check This binlog is closed!
#binlog文件總大小，單位字節
Check This binlog total size:399899873(bytes)
#load data infile場景不做檢查
Note:load data infile not check!
-------------Total now--------------
#事務總數
Trx total[counts]:1345
#event總數
Event total[counts]:58072
#最大的事務大小
Max trx event size:7986(bytes) Pos:560221[0X88C5D]
#平均每秒寫binlog大小
Avg binlog size(/sec):610534.125(bytes)[596.225(kb)]
#平均每分鐘寫binlog大小
Avg binlog size(/min):36632048.000(bytes)[35773.484(kb)]
#binlog分配大小
--Piece view:
(1)Time:1671419439-1671420094(655(s)) piece:19994993(bytes)[19526.359(kb)]
(2)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(3)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(4)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(5)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(6)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(7)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(8)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(9)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(10)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(11)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(12)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(13)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(14)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(15)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(16)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(17)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(18)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(19)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
(20)Time:1671420094-1671420094(0(s)) piece:19994993(bytes)[19526.359(kb)]
#超過大事務規定的事務
--Large than 2000000(bytes) trx:
(1)Trx_size:13310235(bytes)[12998.276(kb)] trx_begin_p:560029[0X88B9D] trx_end_p:13870264[0XD3A4B8]
(2)Trx_size:385990249(bytes)[376943.594(kb)] trx_begin_p:13909131[0XD43C8B] trx_end_p:399899380[0X17D5FAF4]
Total large trx count size(kb):#389941.870(kb)
#超過規定長時間未提交的事務
--Large than 10(secs) trx:
No trx find!
#每張表執行對應操作的binlog大小和次數
--Every Table binlog size(bytes) and times:
Note:size unit is bytes
---(1)Current Table:test.sbtest2::
Insert:binlog size(0(Bytes)) times(0)
Update:binlog size(107440(Bytes)) times(1343)
Delete:binlog size(0(Bytes)) times(0)
Total:binlog size(107440(Bytes)) times(1343)
---(2)Current Table:test.sbtest1::
Insert:binlog size(0(Bytes)) times(0)
Update:binlog size(399300036(Bytes)) times(50001)
Delete:binlog size(0(Bytes)) times(0)
Total:binlog size(399300036(Bytes)) times(50001)
---Total binlog dml event size:399407476(Bytes) times(51344)
對于挽救，也即是第三個問題，當然是對癥下藥了，利用排查階段找出的信息，讓業務側去改造了。如果業務側頑固拖拉，拒不改造，下次晚上半夜收到告警的時候先一個電話打給業務人員，要熬夜一起熬，哈哈，開個玩笑。DBA同學大多數都像我一樣性格溫和的。好了，就到這里吧。
