作者：徐文梁

愛(ài)可生DBA成員，負(fù)責(zé)客戶項(xiàng)目的需求和維護(hù)。目前在數(shù)據(jù)庫(kù)新手村打怪升級(jí)中。喜歡垂釣，如果你也喜歡垂釣，可以約個(gè)晴好天氣，咱們一邊釣魚(yú)一邊聊聊數(shù)據(jù)庫(kù)，豈不快哉。

 

本文來(lái)源：原創(chuàng)投稿

* 愛(ài)可生開(kāi)源社區(qū)出品，原創(chuàng)內(nèi)容未經(jīng)授權(quán)不得隨意使用，轉(zhuǎn)載請(qǐng)聯(lián)系小編并注明來(lái)源。

問(wèn)題現(xiàn)象

某天早上，正在搬磚，客戶發(fā)來(lái)消息，反饋某個(gè)實(shí)例主從延時(shí)值反復(fù)在一萬(wàn)多到0之間來(lái)回跳動(dòng)，如下:

手動(dòng)執(zhí)行show slave statusG命令查看Seconds_Behind_Master延時(shí)值，結(jié)果如下：

問(wèn)題定位

接到問(wèn)題，作為一個(gè)認(rèn)真工作的我，立馬行動(dòng)起來(lái)。首先確認(rèn)了下客戶的數(shù)據(jù)庫(kù)版本，客戶反饋是5.7.31，緊接著找客戶確認(rèn)了下復(fù)制方式，如下圖:

客戶現(xiàn)場(chǎng)的slave_parallel_type值為DATABASE,slave_parallel_workers值為0，此時(shí)主從同步使用的是單SQL線程方式，在遇到大事務(wù)時(shí)產(chǎn)生延遲的可能性更大。推薦客戶換成MTS方式，但是客戶反饋之前一直使用的是該種方式，之前未發(fā)生此種現(xiàn)象，需要排查原因。

于是和客戶確認(rèn)異常期間是否有業(yè)務(wù)變動(dòng)，客戶反饋發(fā)生問(wèn)題之前有新業(yè)務(wù)上線，qps相對(duì)平時(shí)大很多，同時(shí)存在大量insert和update批量寫(xiě)操作，另外，客戶服務(wù)器使用的云服務(wù)器，配置不高。出現(xiàn)問(wèn)題后，新業(yè)務(wù)已經(jīng)臨時(shí)下線。

了解背景后，就有了排查的方向了。從根源進(jìn)行分析，second-behind-master值與三個(gè)值有關(guān)，1.當(dāng)前從服務(wù)器的系統(tǒng)時(shí)間。2.從庫(kù)服務(wù)器和主庫(kù)服務(wù)器的系統(tǒng)時(shí)間的差值。3.mi->last_timestamp。

對(duì)于單線程模式下的dml操作，記錄在binlog中，query_event 的ev->exec_time基本為0，可以忽略，因?yàn)閝uery_event的exec_time只記錄第一條數(shù)據(jù)更改消耗的時(shí)間，且我們一般看到是begin。所以last_master_timestamp就基本等于各個(gè)event中header的timestamp。一個(gè)事務(wù)中，GTID_EVENT和XID_EVENT中記錄的是提交時(shí)刻的時(shí)間，而對(duì)于其他event都是命令發(fā)起時(shí)刻的時(shí)間，此時(shí)second-behind-master的計(jì)算方式為從庫(kù)服務(wù)器時(shí)間-各個(gè)event中header中time stamp的時(shí)間-主從服務(wù)器時(shí)間差，因此如果存在長(zhǎng)時(shí)間未提交的事務(wù)或者存在大事務(wù)在SQL線程應(yīng)用的時(shí)候可能會(huì)觀察到seconds_behind_master的瞬間跳動(dòng)。

由于目前新業(yè)務(wù)已經(jīng)下線，業(yè)務(wù)量已經(jīng)漸漸恢復(fù)到正常狀態(tài)，故暫未做其他處理，建議客戶觀察一段時(shí)間，一段時(shí)間后客戶反饋恢復(fù)正常，到此，問(wèn)題解決了。

問(wèn)題思考

問(wèn)題解決了，但是愛(ài)琢磨的我卻陷入了思考。腦海中浮現(xiàn)出幾個(gè)問(wèn)題，第一，怎樣盡可能避免這種現(xiàn)象？第二，怎么確定是否有長(zhǎng)時(shí)間未提交的事務(wù)和大事務(wù)呢？第三，發(fā)現(xiàn)這種問(wèn)題如何挽救呢?

其實(shí)從事務(wù)發(fā)展歷程來(lái)看，這三個(gè)問(wèn)題也恰恰對(duì)應(yīng)著問(wèn)題處理過(guò)程中的預(yù)防，診治，治療三個(gè)階段。

對(duì)于預(yù)防，即第一個(gè)問(wèn)題，可以從以下幾個(gè)點(diǎn)出發(fā):1.生產(chǎn)環(huán)境條件允許的情況下建議開(kāi)啟并行復(fù)制。2.在業(yè)務(wù)上線前進(jìn)行業(yè)務(wù)量評(píng)估和SQL審核，避免某些不規(guī)范SQL或業(yè)務(wù)邏輯導(dǎo)致出現(xiàn)上述問(wèn)題。

對(duì)于排查，即第二個(gè)問(wèn)題，排查長(zhǎng)時(shí)間未提交的事務(wù)或者大事務(wù)可以通過(guò)show processlist命令或查看information_schema.innodb_trx表進(jìn)行排查，但是這個(gè)只能查詢(xún)當(dāng)前的事務(wù)，對(duì)于歷史的則無(wú)法進(jìn)行查找，此時(shí)可以通過(guò)MySQLbinlog或者my2sql工具解析binlog日志，但是結(jié)果往往不直觀，咨詢(xún)了一些前輩，推薦了一款infobin工具，自己測(cè)試了下還是挺好用的，使用示例:

執(zhí)行命令 infobin mysql-bin.000005 20 2000000 10 -t >/root/result.log

其中，mysql-bin.000005表示需要解析的binlog文件名，20表示是分片數(shù)量,將binlog分為大小相等的片段，生成時(shí)間越短則這段時(shí)間生成binlog量越大，則事務(wù)越頻繁，2000000表示將大于2M左右的事物定義為大事務(wù)，10表示將大于10秒未提交的事物定義為長(zhǎng)期未提交的事務(wù)，-t 表示不做詳細(xì)event解析輸出，僅僅獲取相應(yīng)的結(jié)果。

輸出結(jié)果如下:

#表示是小端平臺(tái)
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不在寫(xiě)入
Check This binlog is closed!
#binlog文件總大小，單位字節(jié)
Check This binlog total size:399899873(bytes)
#load data infile場(chǎng)景不做檢查
Note:load data infile not check!
-------------Total now--------------
#事務(wù)總數(shù)
Trx total[counts]:1345
#event總數(shù)
Event total[counts]:58072
#最大的事務(wù)大小
Max trx event size:7986(bytes) Pos:560221[0X88C5D]
#平均每秒寫(xiě)binlog大小
Avg binlog size(/sec):610534.125(bytes)[596.225(kb)]
#平均每分鐘寫(xiě)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)]
#超過(guò)大事務(wù)規(guī)定的事務(wù)
--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)
#超過(guò)規(guī)定長(zhǎng)時(shí)間未提交的事務(wù)
--Large than 10(secs) trx:
No trx find!
#每張表執(zhí)行對(duì)應(yīng)操作的binlog大小和次數(shù)
--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)

對(duì)于挽救，也即是第三個(gè)問(wèn)題，當(dāng)然是對(duì)癥下藥了，利用排查階段找出的信息，讓業(yè)務(wù)側(cè)去改造了。如果業(yè)務(wù)側(cè)頑固拖拉，拒不改造，下次晚上半夜收到告警的時(shí)候先一個(gè)電話打給業(yè)務(wù)人員，要熬夜一起熬，哈哈，開(kāi)個(gè)玩笑。DBA同學(xué)大多數(shù)都像我一樣性格溫和的。好了，就到這里吧。