當前位置：首頁 > 运维知识 > 数据库 >内容正文

数据库

MySQL的诡异同步问题-重复执行一条relay-log

發(fā)布時間：2023/12/20 数据库 43 豆豆

生活随笔收集整理的這篇文章主要介紹了 MySQL的诡异同步问题-重复执行一条relay-log 小編覺得挺不錯的,現(xiàn)在分享給大家,幫大家做個參考.

MySQL的詭異同步問題

近期遇到一個詭異的MySQL同步問題，經(jīng)過多方分析和定位后發(fā)現(xiàn)居然是由于備份引發(fā)的，非常的奇葩，特此記錄一下整個問題的分析和定位過程。

現(xiàn)象

同事擴容的一臺slave死活追不上同步，具體的現(xiàn)象是SBM=0，但是Exec_Master_Log_Pos執(zhí)行的位置和Read_Master_Log_Pos完全對不上，且服務(wù)器本身CPU和IO都消耗的非常厲害。

——total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--usr sys idl wai hiq siq| read writ| recv send| in out | int csw1 0 99 0 0 0|8667B 862k| 0 0 | 0 0 | 536 8421 3 93 2 0 1| 0 102M| 112k 12k| 0 0 | 21k 50k1 3 94 2 0 1| 0 101M| 89k 5068B| 0 0 | 21k 49k1 3 93 2 0 1| 0 103M| 97k 5170B| 0 0 | 21k 50k1 4 93 2 0 1| 0 103M| 80k 15k| 0 0 | 21k 50k1 4 92 2 0 1| 0 102M| 112k 8408B| 0 0 | 21k 50k

分析

由于SBM并不能真正代表同步的狀態(tài)，所以最開始我們認為有一個比較大的event在執(zhí)行過程中，所以導(dǎo)致SBM=0但是pos位置不對，但是在觀察一段之后發(fā)現(xiàn)，現(xiàn)象并沒有變化，并且Relay_Log_File始終在同一個文件上。

為了找到這個現(xiàn)象的原因，我們使用strace來分析。由于服務(wù)器的現(xiàn)象是有非常大的磁盤寫操作，故先使用iotop定位寫入量較大的thread id，然后通過strace -p來分析。

通過strace采集的信息如下：

read(38, "376bin>303275T1721325322Bg000k0000040005.5.31-"..., 8192) = 150lseek(36, 0, SEEKSET) = 0write(36, "./relay-bin.000914n107nmysql-bin"..., 44) = 44read(38, "", 8042) = 0close(38) = 0lseek(36, 0, SEEKSET) = 0write(36, "./relay-bin.000914n107nmysql-bin"..., 44) = 44unlink("./relay-bin.rec") = -1 ENOENT (No such file or directory)open("./relay-bin.rec", ORDWR|OCREAT, 0660) = 38lseek(38, 0, SEEKCUR) = 0fsync(38) = 0lseek(35, 0, SEEKSET) = 0read(35, "./relay-bin.000914n./relay-bin.0"..., 8192) = 437lseek(35, 0, SEEKSET) = 0write(35, "./relay-bin.000914n./relay-bin.0"..., 437) = 437lseek(35, 437, SEEKSET) = 437read(35, "", 8192) = 0lseek(35, 0, SEEKEND) = 437fsync(35) = 0lseek(38, 0, SEEKSET) = 0close(38) = 0unlink("./relay-bin.rec") = 0lseek(35, 0, SEEKSET) = 0read(35, "./relay-bin.000914n./relay-bin.0"..., 437) = 437open("./relay-bin.000914", ORDONLY) = 38lseek(38, 0, SEEKCUR) = 0read(38, "376bin>303275T1721325322Bg000k0000040005.5.31-"..., 8192) = 150lseek(36, 0, SEEKSET) = 0write(36, "./relay-bin.000914n107nmysql-bin"..., 44) = 44read(38, "", 8042) = 0

從上面可以看出MySQLD在不斷的read和write35、36、38這3個文件。通過內(nèi)容，我們大概可以看出這3個文件應(yīng)該是relay-bin.index、relay-bin.000914和relay-log.info這3個文件。但是如何確定這3個文件呢？這時候就需要lsof了，通過lsof我們可以發(fā)現(xiàn)每個pid在proc下都會有一個fd的目錄，在這個目錄中就是各個文件的鏈接，通過fd號就可以直接確定具體是那個文件了

cd /proc/$pid/fdll -hlr-x------ 1 root root 64 Jan 31 12:44 0 -> /dev/nulll-wx------ 1 root root 64 Jan 31 12:44 1 -> /data1/mysql3361/error.loglrwx------ 1 root root 64 Jan 31 12:44 10 -> /data1/mysql3361/iblogfile1lrwx------ 1 root root 64 Jan 31 12:44 11 -> /data1/mysql3361/iblogfile2lr-x------ 1 root root 64 Jan 31 12:44 12 -> /data1/mysql3361/relay-bin.reclrwx------ 1 root root 64 Jan 31 12:44 13 -> /data1/mysql3361/ibF0ovt9 (deleted)lrwx------ 1 root root 64 Jan 31 12:44 14 -> socket:1042425539lrwx------ 1 root root 64 Jan 31 12:44 15 -> /data1/mysql3361/relay-bin.indexlrwx------ 1 root root 64 Jan 31 12:44 16 -> socket:1042425540lrwx------ 1 root root 64 Jan 31 12:44 17 -> /data1/mysql3361/sngdb/sngrankscore6.ibdlrwx------ 1 root root 64 Jan 31 12:44 18 -> /data1/mysql3361/mysql/host.MYIlrwx------ 1 root root 64 Jan 31 12:44 19 -> /data1/mysql3361/mysql/host.MYDl-wx------ 1 root root 64 Jan 31 12:44 2 -> /data1/mysql3361/error.loglrwx------ 1 root root 64 Jan 31 12:44 20 -> /data1/mysql3361/mysql/user.MYIlrwx------ 1 root root 64 Jan 31 12:44 21 -> /data1/mysql3361/mysql/user.MYD

定位

至此，我們已經(jīng)非常確定是由于這3個文件導(dǎo)致，那么具體看一下這3個文件有什么異常？在挨個檢查后發(fā)現(xiàn)，relay-bin.index文件非常異常，同樣的relay-bin在index中存在了兩行，這會不會就是問題的原因呢？

cat relay-bin.index./relay-bin.000914./relay-bin.000914./relay-bin.000915./relay-bin.000916cat relay-log.info./relay-bin.000914107mysql-bin.000724107

人肉去掉一行之后，發(fā)現(xiàn)一切變正常了，那么看來問題的原因就在于relay-bin.index中存在著兩行同樣的記錄導(dǎo)致的了，但是為什么會導(dǎo)致這種現(xiàn)象呢？

再分析

這時候純想已經(jīng)沒有用了，只好從code中尋找答案，主要看slave.cc和log.cc。

具體來說就是MySQL在啟動slave的時候會從relay-log.info中讀取對應(yīng)的filename和pos然后去execute relay log event，當執(zhí)行完畢之后會進行刪除操作，mysql會使用reinit_io_cache重置relay-log.index文件的文件指針，之后再采用find_log_pos里面的代碼mcmcmp從relay-log.index第一行確認所需偏移，這時候就又回到了同樣的relay-log，于是死循環(huán)產(chǎn)生了。

int MYSQLBINLOGfindlogpos(LOGINFO linfo, const char logname,bool needlock)(void) reinitiocache(&indexfile, READCACHE, (myofft) 0, 0, 0);for (;;)if (!logname(lognamelen == fnamelen-1 && fullfnamelognamelen == 'n' &&!memcmp(fullfname, fulllogname, lognamelen)))DBUGPRINT("info", ("Found log file entry"));fullfnamefnamelen-1]= 0; // remove last nlinfo->indexfilestartoffset= offset;linfo->indexfileoffset = mybtell(&indexfile);break;}}}}

簡單來說：

sql-thread讀取relay-log.info，開始從000914開始執(zhí)行。

執(zhí)行完畢之后，從index中讀取下一個relay-log，發(fā)現(xiàn)還是000914

于是將指針又定位到index文件的第一行

然后死循環(huán)就產(chǎn)生了

至于之后的000915等文件是由于io-thread生成的，和sql-thread無關(guān)，可以忽略

至此，出現(xiàn)SBM=0現(xiàn)象，并且產(chǎn)生很大的IO消耗的原因已經(jīng)確定，就是由于relay-bin.index文件中的重復(fù)行導(dǎo)致。但是為什么會產(chǎn)生同樣的兩行數(shù)據(jù)呢？

分析產(chǎn)生原因

首先，這個絕對不可能是人閑的抽風(fēng)手動vi的。

其次，手動執(zhí)行flush logs的時候relay-log會自動增加一個。

再次，眾所周知，MySQl再啟動的時候會自動執(zhí)行類似flush logs的操作，將relay-log自動向下創(chuàng)建一個。

結(jié)合上面的信息，并在同事的不斷追查下，最終發(fā)現(xiàn)是由于我們的備份導(dǎo)致的。

第一、我們每天都會進行數(shù)據(jù)庫的冷備，使用rsync方式。

第二、我們每天會對日志進行歸檔操作，定時執(zhí)行flush logs。

當以上兩個操作遭遇到一起之后，就會發(fā)生在拷貝完relay-log和relay-bin.index之間執(zhí)行了flush logs操作，這樣就導(dǎo)致relay-log和relay-bin.index中不等，也就導(dǎo)致了使用這個備份進行擴容都會產(chǎn)生index文件中的重復(fù)行。

總結(jié)改進

終于，這么奇葩，這么小概率的一個問題終于找到根源，在此之前，真是想破頭也想不出來到底是怎么回事。感謝 @zolker @大自在真人 @zhangyang8的深入調(diào)研和追查，沒有鍥而不舍的精神，我們是不會追查到這種地步的。

然后就是改進了：

加強對備份的文件一致性效驗，從根源上避免。

加強還原程序的兼容性，由于index文件對于擴容的slave并沒有實際意義，所以如果發(fā)現(xiàn)重復(fù)行可以直接置空index文件。

轉(zhuǎn)載于:https://www.cnblogs.com/billyxp/p/4264020.html

總結(jié)

以上是生活随笔為你收集整理的MySQL的诡异同步问题-重复执行一条relay-log的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。