12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
ADADADADAD
mysql数据库 时间:2024-11-26 22:11:58
作者:文/会员上传
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
12-09
一、触发条件本案列我测试过4个版本percona Mysql 5.7.14官方社区 Mysql 5.7.17percona Mysql 5.7.19percona Mysql 5.7.15其中percona Mysql 5.7.14和官方社区 Mysql 5.7.1
以下为本文的正文内容,内容仅供参考!本站为公益性网站,复制本文以及下载DOC文档全部免费。
本案列我测试过4个版本
percona Mysql 5.7.14
官方社区 Mysql 5.7.17
percona Mysql 5.7.19
percona Mysql 5.7.15
其中percona Mysql 5.7.14和官方社区 Mysql 5.7.17有这个问题。其他版本未知
已知percona Mysql 5.7.14或者官方社区 Mysql 5.7.17。
mysqldump备份没有使用 -F, --flush-logs选项
Gtid打开。
二、故障描述本故障主要是新搭建的Gtid主从库,运行一段时间后重启主从必然报错如下:
Last_IO_Error:Gotfatalerror1236frommasterwhenreadingdatafrombinarylog:'TheslaveisconnectingusingCHANGEMASTERTOMASTER_AUTO_POSITION=1,butthemasterhaspurgedbinarylogscontainingGTIDsthattheslaverequires.'三、故障分析
为什么重启后会报错找到不事物呢,然后发现这个Gtid事物在主库的binlog中已经没有了,应该是很久以前的。其实这个问题我们要回到mysqldump出来的文件如何进行Gtid的初始化以及mysql.gtid_executed表中。
在mysqldump不使用--set-gtid-purged的时候必然会在dump出来的脚本中包含
--GTIDstateatthebeginningofthebackupSET@@GLOBAL.GTID_PURGED='e859a28b-b66d-11e7-8371-000c291f347d:1-41';
这样一个设置GTID_PURGED的语句,它包含了主库上已经执行的全部Gtid事物。从第五节的源码和总结部分我们知道这个语句至少做了三个更改(DBA可见的只有三个):
mysql.gtid_executed表的写入
gtid_executed变量的修改
gtid_purged变量的修改
而完成了这一步实际上mysql.gtid_executed表是包含了全部的执行过的Gtid事物的,但是随后我们看到dump脚本包含了如下语句
210--Tablestructurefortable`gtid_executed`211--212213DROPTABLEIFEXISTS`gtid_executed`;214/*!40101SET@saved_cs_client=@@character_set_client*/;215/*!40101SETcharacter_set_client=utf8*/;216CREATETABLE`gtid_executed`(217`source_uuid`char(36)NOTNULLCOMMENT'uuidofthesourcewherethetransactionwasoriginallyexecuted.',218`interval_start`bigint(20)NOTNULLCOMMENT'Firstnumberofinterval.',219`interval_end`bigint(20)NOTNULLCOMMENT'Lastnumberofinterval.',220PRIMARYKEY(`source_uuid`,`interval_start`)221)ENGINE=InnoDBDEFAULTCHARSET=utf8;222/*!40101SETcharacter_set_client=@saved_cs_client*/;223224--225--Dumpingdatafortable`gtid_executed`226--227228LOCKTABLES`gtid_executed`WRITE;229/*!40000ALTERTABLE`gtid_executed`DISABLEKEYS*/;230INSERTINTO`gtid_executed`VALUES('e859a28b-b66d-11e7-8371-000c291f347d',1,32);231/*!40000ALTERTABLE`gtid_executed`ENABLEKEYS*/;232UNLOCKTABLES;
显然这里我们在source的时候从库的mysql.gtid_executed将被重新初始化为:
'e859a28b-b66d-11e7-8371-000c291f347d',1,32
而实际的已经执行过的Gtid是:
'e859a28b-b66d-11e7-8371-000c291f347d:1-41';
如前文第五节我们通过源码分析后总结如下:
mysql.gtid_executed表修改时机在binlog发生切换(rotate)的时候保存直到上一个binlog文件执行过的全部Gtid,它不是实时更新的。
因此此时表中并没有完全包含全部执行过的Gtid事物,而在前文第六节的源码分析中我们知道在Gtid模块启动的时候必须要读取两个Gtid持久化的介质:
mysql.gtid_executed
binlog
来判断Gtid的集合,显然从库不可能在binlog包含这个Gtid事物,所以这样的操作步骤就导致了数据库从库后的报错,而这里的正确的步骤是压根不进行mysql.gtid_executed的重建和导入,我发现在percona Mysql 5.7.15和percona Mysql 5.7.19正是这样的。但是为了防范这个问题,我在搭建的Gtid从库导完数据后加入了两个个步骤如下:
resetmaster;setglobalgtid_purged='e859a28b-b66d-11e7-8371-000c291f347d:1-41';
这两步也就是为了从新初始化mysql.gtid_executed表,让其正确。
此问题还可以在mysqldump的时候加入-F, --flush-logs选项规避,但是-F会加入如下的MDL LOCK:
2017-12-18T08:16:39.580985Z6QueryFLUSH/*!40101LOCAL*/TABLES2017-12-18T08:16:39.612598Z6QueryFLUSHTABLESWITHREADLOCK2017-12-18T08:16:39.613406Z6Refresh/root/mysql5.7.14/percona-server-5.7.14-7/sql/mysqld,Version:5.7.14-7-debug-log(Sourcedistribution).startedwith:Tcpport:13001Unixsocket:/root/mysql5.7.14/percona-server-5.7.14-7/mysql-test/var/tmp/mysqld.1.sockTimeIdCommandArgument2017-12-18T08:16:39.965847Z6QuerySETSESSIONTRANSACTIONISOLATIONLEVELREPEATABLEREAD2017-12-18T08:16:39.966298Z6QuerySTARTTRANSACTION/*!40100WITHCONSISTENTSNAPSHOT*/2017-12-18T08:16:39.966792Z6QuerySHOWVARIABLESLIKE'gtid\_mode'2017-12-18T08:16:39.969587Z6QuerySELECT@@GLOBAL.GTID_EXECUTED2017-12-18T08:16:39.970216Z6QuerySHOWSTATUSLIKE'binlog_snapshot_%'2017-12-18T08:16:39.975242Z6QueryUNLOCKTABLES
这把锁是GLOBAL级别的MDL_SHARED(S)锁,它会等到你说有的SELECT/DML/DDL语句结束后才能获得,同时会堵塞全部的SELECT/DML/DDL虽然持有时间很短如下:
mysql>flushtableswithreadlock;QueryOK,0rowsaffected(0.01sec)2017-08-03T18:19:11.603911Z3[Note](acquire_lock)THISMDLLOCKacquireok!2017-08-03T18:19:11.603947Z3[Note](>MDLPRINT)Threadidis3:2017-08-03T18:19:11.603971Z3[Note](--->MDLPRINT)Namespaceis:GLOBAL2017-08-03T18:19:11.603994Z3[Note](----->MDLPRINT)Mdltypeis:MDL_SHARED(S)2017-08-03T18:19:11.604045Z3[Note](------>MDLPRINT)Mdldurationis:MDL_EXPLICIT2017-08-03T18:19:11.604073Z3[Note](------->MDLPRINT)Mdlstatusis:EMPTY2017-08-03T18:19:11.604133Z3[Note](acquire_lock)THISMDLLOCKacquireok!
当然要了解MDL LOCK的朋友可以参考我的文章
http://blog.itpub.net/7728585/viewspace-2143093/
MYSQL METADATA LOCK(MDL LOCK)学习(1) 理论知识和加锁类型测试
知道了原因后也是很好模拟我使用的版本是社区版5.7.17,搭建过程就是前面说的步骤。只是导完数据后不使用reset master和set gtid_purged表进行重新初始化mysql.gtid_executed表。搭建完成后做几个事物状态正常如下:
mysql>showslavestatus\G***************************1.row***************************Master_Log_File:binlog.000002Read_Master_Log_Pos:5077Relay_Log_File:test1-relay-bin.000002Relay_Log_Pos:2498Relay_Master_Log_File:binlog.000002Slave_IO_Running:YesSlave_SQL_Running:YesExec_Master_Log_Pos:5077Relay_Log_Space:2705Last_IO_Errno:0Last_IO_Error:Seconds_Behind_Master:0Retrieved_Gtid_Set:e859a28b-b66d-11e7-8371-000c291f347d:42-49Executed_Gtid_Set:e859a28b-b66d-11e7-8371-000c291f347d:1-49Auto_Position:1
但是这个时候我们发现mysql.gtid_executed表已经出现了问题如下:
mysql>select*fromgtid_executed;+--------------------------------------+----------------+--------------+|source_uuid|interval_start|interval_end|+--------------------------------------+----------------+--------------+|e859a28b-b66d-11e7-8371-000c291f347d|1|32||e859a28b-b66d-11e7-8371-000c291f347d|42|42||e859a28b-b66d-11e7-8371-000c291f347d|43|43||e859a28b-b66d-11e7-8371-000c291f347d|44|44||e859a28b-b66d-11e7-8371-000c291f347d|45|45||e859a28b-b66d-11e7-8371-000c291f347d|46|46||e859a28b-b66d-11e7-8371-000c291f347d|47|47||e859a28b-b66d-11e7-8371-000c291f347d|48|48||e859a28b-b66d-11e7-8371-000c291f347d|49|49|+--------------------------------------+----------------+--------------+
很容易发现33-41之间是没有持久化的。如果这个时候如果我们使用purge binary logs to 来清理掉主库的日志那么必将出现问题,如果不清理也会出现Gtid事物重新执行的情况。我们做清理模拟线上错误。主库执行:
mysql>showbinarylogs;+---------------+-----------+|Log_name|File_size|+---------------+-----------+|binlog.000001|9974||binlog.000002|5121||binlog.000003|194|+---------------+-----------+3rowsinset(0.01sec)mysql>purgebinarylogsto'binlog.000003';QueryOK,0rowsaffected(0.04sec)mysql>showbinarylogs;+---------------+-----------+|Log_name|File_size|+---------------+-----------+|binlog.000003|194|+---------------+-----------+1rowinset(0.00sec)
备库重启后错误重现:
mysql>showslavestatus\G***************************1.row***************************Slave_IO_State:Master_Host:192.168.190.62Master_User:replMaster_Port:3308Connect_Retry:60Master_Log_File:binlog.000003Read_Master_Log_Pos:194Relay_Log_File:test1-relay-bin.000005Relay_Log_Pos:4Relay_Master_Log_File:binlog.000003Slave_IO_Running:NoSlave_SQL_Running:YesExec_Master_Log_Pos:194Relay_Log_Space:194Last_IO_Errno:1236Last_IO_Error:Gotfatalerror1236frommasterwhenreadingdatafrombinarylog:'TheslaveisconnectingusingCHANGEMASTERTOMASTER_AUTO_POSITION=1,butthemasterhaspurgedbinarylogscontainingGTIDsthattheslaverequires.'Slave_SQL_Running_State:Slavehasreadallrelaylog;waitingformoreupdatesRetrieved_Gtid_Set:e859a28b-b66d-11e7-8371-000c291f347d:42-49Executed_Gtid_Set:e859a28b-b66d-11e7-8371-000c291f347d:1-32:42-49Auto_Position:1
我们发现I/O thread 试图获取主库的33-41的Gtid事物的事物,已经不能获取,实际上即使能获取也会造成事物的重新执行,我们看到Executed_Gtid_Set已经出现了两个连续的区间:
Executed_Gtid_Set:e859a28b-b66d-11e7-8371-000c291f347d:1-32:42-49
11-20
11-19
11-20
11-20
11-20
11-19
11-20
11-20
11-19
11-20
11-19
11-19
11-19
11-19
11-19
11-19