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

时间 2019-12-13

标签 mysql 诡异同步问题重复执行一条 relay log 栏目 MySQL 繁體版

原文原文链接

MySQL的诡异同步问题

近期遇到一个诡异的MySQL同步问题，通过多方分析和定位后发现竟然是因为备份引起的，很是的奇葩，特此记录一下整个问题的分析和定位过程。mysql

现象

同事扩容的一台slave死活追不上同步，具体的现象是SBM=0，可是Exec_Master_Log_Pos执行的位置和Read_Master_Log_Pos彻底对不上，且服务器自己CPU和IO都消耗的很是厉害。sql

——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采集的信息以下：socket

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号就能够直接肯定具体是那个文件了spa

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。code

具体来讲就是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，因而死循环产生了。blog

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;

    }

    }

  }

}

简单来讲：

sql-thread读取relay-log.info，开始从000914开始执行。
执行完毕以后，从index中读取下一个relay-log，发现仍是000914
因而将指针又定位到index文件的第一行
而后死循环就产生了
至于以后的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的深刻调研和追查，没有持之以恒的精神，咱们是不会追查到这种地步的。

而后就是改进了：

增强对备份的文件一致性效验，从根源上避免。
增强还原程序的兼容性，因为index文件对于扩容的slave并无实际意义，因此若是发现重复行能够直接置空index文件。