MySQL的詭異同步問題-重複執行一條relay-log

MySQL的詭異同步問題

近期遇到一個詭異的MySQL同步問題，通過多方分析和定位後發現竟然是因爲備份引起的，很是的奇葩，特此記錄一下整個問題的分析和定位過程。

現象

同事擴容的一臺slave死活追不上同步，具體的現象是SBM=0，可是Exec_Master_Log_Pos執行的位置和Read_Master_Log_Pos徹底對不上，且服務器自己CPU和IO都消耗的很是厲害。

 

——total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--

usr sys idl wai hiq siq| read writ| recv send| in out | int csw

1 0 99 0 0 0|8667B 862k| 0 0 | 0 0 | 536 842

1 3 93 2 0 1| 0 102M| 112k 12k| 0 0 | 21k 50k

1 3 94 2 0 1| 0 101M| 89k 5068B| 0 0 | 21k 49k

1 3 93 2 0 1| 0 103M| 97k 5170B| 0 0 | 21k 50k

1 4 93 2 0 1| 0 103M| 80k 15k| 0 0 | 21k 50k

1 4 92 2 0 1| 0 102M| 112k 8408B| 0 0 | 21k 50k

 

 

分析

因爲SBM並不能真正表明同步的狀態，因此最開始咱們認爲有一個比較大的event在執行過程當中，因此致使SBM=0可是pos位置不對，可是在觀察一段以後發現，現象並無變化，而且Relay_Log_File始終在同一個文件上。

爲了找到這個現象的緣由，咱們使用strace來分析。因爲服務器的現象是有很是大的磁盤寫操做，故先使用iotop定位寫入量較大的thread id，而後經過strace -p來分析。

經過strace採集的信息以下：

 

read(38, "376bin>303275T1721325322Bg000k0000040005.5.31-"..., 8192) = 150

lseek(36, 0, SEEKSET) = 0

write(36, "./relay-bin.000914n107nmysql-bin"..., 44) = 44

read(38, "", 8042) = 0

close(38) = 0

lseek(36, 0, SEEKSET) = 0

write(36, "./relay-bin.000914n107nmysql-bin"..., 44) = 44

unlink("./relay-bin.rec") = -1 ENOENT (No such file or directory)

open("./relay-bin.rec", ORDWR|OCREAT, 0660) = 38

lseek(38, 0, SEEKCUR) = 0

fsync(38) = 0

lseek(35, 0, SEEKSET) = 0

read(35, "./relay-bin.000914n./relay-bin.0"..., 8192) = 437

lseek(35, 0, SEEKSET) = 0

write(35, "./relay-bin.000914n./relay-bin.0"..., 437) = 437

lseek(35, 437, SEEKSET) = 437

read(35, "", 8192) = 0

lseek(35, 0, SEEKEND) = 437

fsync(35) = 0

lseek(38, 0, SEEKSET) = 0

close(38) = 0

unlink("./relay-bin.rec") = 0

lseek(35, 0, SEEKSET) = 0

read(35, "./relay-bin.000914n./relay-bin.0"..., 437) = 437

open("./relay-bin.000914", ORDONLY) = 38

lseek(38, 0, SEEKCUR) = 0

read(38, "376bin>303275T1721325322Bg000k0000040005.5.31-"..., 8192) = 150

lseek(36, 0, SEEKSET) = 0

write(36, "./relay-bin.000914n107nmysql-bin"..., 44) = 44

read(38, "", 8042) = 0

 

 

從上面能夠看出MySQLD在不斷的read和write35、36、38這3個文件。經過內容，咱們大概能夠看出這3個文件應該是relay-bin.index、relay-bin.000914和relay-log.info這3個文件。可是如何肯定這3個文件呢？ 這時候就須要lsof了，經過lsof咱們能夠發現每一個pid在proc下都會有一個fd的目錄，在這個目錄中就是各個文件的連接，經過fd號就能夠直接肯定具體是那個文件了

 

cd /proc/$pid/fd

ll -h

lr-x------ 1 root root 64 Jan 31 12:44 0 -> /dev/null

l-wx------ 1 root root 64 Jan 31 12:44 1 -> /data1/mysql3361/error.log

lrwx------ 1 root root 64 Jan 31 12:44 10 -> /data1/mysql3361/iblogfile1

lrwx------ 1 root root 64 Jan 31 12:44 11 -> /data1/mysql3361/iblogfile2

lr-x------ 1 root root 64 Jan 31 12:44 12 -> /data1/mysql3361/relay-bin.rec

lrwx------ 1 root root 64 Jan 31 12:44 13 -> /data1/mysql3361/ibF0ovt9 (deleted)

lrwx------ 1 root root 64 Jan 31 12:44 14 -> socket:1042425539

lrwx------ 1 root root 64 Jan 31 12:44 15 -> /data1/mysql3361/relay-bin.index

lrwx------ 1 root root 64 Jan 31 12:44 16 -> socket:1042425540

lrwx------ 1 root root 64 Jan 31 12:44 17 -> /data1/mysql3361/sngdb/sngrankscore6.ibd

lrwx------ 1 root root 64 Jan 31 12:44 18 -> /data1/mysql3361/mysql/host.MYI

lrwx------ 1 root root 64 Jan 31 12:44 19 -> /data1/mysql3361/mysql/host.MYD

l-wx------ 1 root root 64 Jan 31 12:44 2 -> /data1/mysql3361/error.log

lrwx------ 1 root root 64 Jan 31 12:44 20 -> /data1/mysql3361/mysql/user.MYI

lrwx------ 1 root root 64 Jan 31 12:44 21 -> /data1/mysql3361/mysql/user.MYD

 

 

定位

至此，咱們已經很是肯定是因爲這3個文件致使，那麼具體看一下這3個文件有什麼異常？在挨個檢查後發現，relay-bin.index文件很是異常，一樣的relay-bin在index中存在了兩行，這會不會就是問題的緣由呢？

 

cat relay-bin.index

./relay-bin.000914

./relay-bin.000914

./relay-bin.000915

./relay-bin.000916

cat relay-log.info

./relay-bin.000914

107

mysql-bin.000724

107

 

 

人肉去掉一行以後，發現一切變正常了，那麼看來問題的緣由就在於relay-bin.index中存在着兩行一樣的記錄致使的了，可是爲何會致使這種現象呢？

再分析

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

具體來講就是MySQL在啓動slave的時候會從relay-log.info中讀取對應的filename和pos而後去execute relay log event，當執行完畢以後會進行刪除操做，mysql會使用reinit_io_cache重置relay-log.index文件的文件指針，以後再採用find_log_pos裏面的代碼mcmcmp從relay-log.index第一行確認所需偏移，這時候就又回到了一樣的relay-log，因而死循環產生了。

 

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 n

      linfo->indexfilestartoffset= offset;

      linfo->indexfileoffset = mybtell(&indexfile);

      break;

    }

    }

  }

}

　　

 

簡單來講：

1. sql-thread讀取relay-log.info，開始從000914開始執行。
2. 執行完畢以後，從index中讀取下一個relay-log，發現仍是000914
3. 因而將指針又定位到index文件的第一行
4. 而後死循環就產生了
5. 至於以後的000915等文件是因爲io-thread生成的，和sql-thread無關，能夠忽略

至此，出現SBM=0現象，而且產生很大的IO消耗的緣由已經肯定，就是因爲relay-bin.index文件中的重複行致使。可是爲何會產生一樣的兩行數據呢？

分析產生緣由

首先，這個絕對不多是人閒的抽風手動vi的。

其次，手動執行flush logs的時候relay-log會自動增長一個。

再次，衆所周知，MySQl再啓動的時候會自動執行相似flush logs的操做，將relay-log自動向下建立一個。

結合上面的信息，並在同事的不斷追查下，最終發現是因爲咱們的備份致使的。

第1、咱們天天都會進行數據庫的冷備，使用rsync方式。

第2、咱們天天會對日誌進行歸檔操做，定時執行flush logs。

當以上兩個操做遭遇到一塊兒以後，就會發生在拷貝完relay-log和relay-bin.index之間執行了flush logs操做，這樣就致使relay-log和relay-bin.index中不等，也就致使了使用這個備份進行擴容都會產生index文件中的重複行。

總結改進

終於，這麼奇葩，這麼小几率的一個問題終於找到根源，在此以前，真是想破頭也想不出來究竟是怎麼回事。感謝 @zolker @大自在真人 @zhangyang8的 深刻調研和追查，沒有持之以恆的精神，咱們是不會追查到這種地步的。

而後就是改進了：

1. 增強對備份的文件一致性效驗，從根源上避免。
2. 增強還原程序的兼容性，因爲index文件對於擴容的slave並無實際意義，因此若是發現重複行能夠直接置空index文件。