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;
}
}
}
}
简单来说：
- 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自动向下创建一个。
结合上面的信息，并在同事的不断追查下，最终发现是由于我们的备份导致的。
第一、我们每天都会进行数据库的冷备，使用rsync方式。
第二、我们每天会对日志进行归档操作，定时执行flush logs。
当以上两个操作遭遇到一起之后，就会发生在拷贝完relay-log和relay-bin.index之间执行了flush logs操作，这样就导致relay-log和relay-bin.index中不等，也就导致了使用这个备份进行扩容都会产生index文件中的重复行。
总结改进
终于，这么奇葩，这么小概率的一个问题终于找到根源，在此之前，真是想破头也想不出来到底是怎么回事。感谢 @zolker @大自在真人 @zhangyang8的 深入调研和追查，没有锲而不舍的精神，我们是不会追查到这种地步的。
然后就是改进了：
- 加强对备份的文件一致性效验，从根源上避免。
- 加强还原程序的兼容性，由于index文件对于扩容的slave并没有实际意义，所以如果发现重复行可以直接置空index文件。
