Mysql 5.7 Gtid內部學習(十) 實際案例(二)
本案例是我真實遇到過的一個坑，也在前文中不止一次的提到，當時也是非常納悶，其實知道原因後只能說為什麼會這麼坑。
一、觸發條件
本案列我測試過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: Got fatal error 1236 from master when reading data from binary log: 'The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.'
三、故障分析
為什麼重啟後會報錯找到不事物呢，然後發現這個Gtid事物在主庫的binlog中已經沒有了，應該是很久以前的。其實這個問題我們要回到mysqldump出來的檔案如何進行Gtid的初始化以及mysql.gtid_executed表中。
在mysqldump不使用--set-gtid-purged的時候必然會在dump出來的指令碼中包含
-- GTID state at the beginning of the backup SET @@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 -- Table structure for table `gtid_executed`
211 --
212
213 DROP TABLE IF EXISTS `gtid_executed`;
214 /*!40101 SET @saved_cs_client = @@character_set_client */;
215 /*!40101 SET character_set_client = utf8 */;
216 CREATE TABLE `gtid_executed` (
217 `source_uuid` char(36) NOT NULL COMMENT 'uuid of the source where the transaction was originally executed.',
218 `interval_start` bigint(20) NOT NULL COMMENT 'First number of interval.',
219 `interval_end` bigint(20) NOT NULL COMMENT 'Last number of interval.',
220 PRIMARY KEY (`source_uuid`,`interval_start`)
221 ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
222 /*!40101 SET character_set_client = @saved_cs_client */;
223
224 --
225 -- Dumping data for table `gtid_executed`
226 --
227
228 LOCK TABLES `gtid_executed` WRITE;
229 /*!40000 ALTER TABLE `gtid_executed` DISABLE KEYS */;
230 INSERT INTO `gtid_executed` VALUES ('e859a28b-b66d-11e7-8371-000c291f347d',1,32);
231 /*!40000 ALTER TABLE `gtid_executed` ENABLE KEYS */;
232 UNLOCK TABLES;
顯然這裡我們在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從庫導完資料後加入了兩個個步驟如下：
reset master； set global gtid_purged='e859a28b-b66d-11e7-8371-000c291f347d:1-41';
這兩步也就是為了從新初始化mysql.gtid_executed表，讓其正確。
此問題還可以在mysqldump的時候加入-F, --flush-logs選項規避，但是-F會加入如下的MDL LOCK：
2017-12-18T08:16:39.580985Z 6 Query FLUSH /*!40101 LOCAL */ TABLES 2017-12-18T08:16:39.612598Z 6 Query FLUSH TABLES WITH READ LOCK 2017-12-18T08:16:39.613406Z 6 Refresh /root/mysql5.7.14/percona-server-5.7.14-7/sql/mysqld, Version: 5.7.14-7-debug-log (Source distribution). started with: Tcp port: 13001 Unix socket: /root/mysql5.7.14/percona-server-5.7.14-7/mysql-test/var/tmp/mysqld.1.sock Time Id Command Argument 2017-12-18T08:16:39.965847Z 6 Query SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ 2017-12-18T08:16:39.966298Z 6 Query START TRANSACTION /*!40100 WITH CONSISTENT SNAPSHOT */ 2017-12-18T08:16:39.966792Z 6 Query SHOW VARIABLES LIKE 'gtid\_mode' 2017-12-18T08:16:39.969587Z 6 Query SELECT @@GLOBAL.GTID_EXECUTED 2017-12-18T08:16:39.970216Z 6 Query SHOW STATUS LIKE 'binlog_snapshot_%' 2017-12-18T08:16:39.975242Z 6 Query UNLOCK TABLES
這把鎖是GLOBAL級別的MDL_SHARED(S)鎖，它會等到你說有的SELECT/DML/DDL語句結束後才能獲得，同時會堵塞全部的SELECT/DML/DDL雖然持有時間很短如下：
mysql> flush tables with read lock; Query OK, 0 rows affected (0.01 sec) 2017-08-03T18:19:11.603911Z 3 [Note] (acquire_lock)THIS MDL LOCK acquire ok! 2017-08-03T18:19:11.603947Z 3 [Note] (>MDL PRINT) Thread id is 3: 2017-08-03T18:19:11.603971Z 3 [Note] (--->MDL PRINT) Namespace is:GLOBAL 2017-08-03T18:19:11.603994Z 3 [Note] (----->MDL PRINT) Mdl type is:MDL_SHARED(S) 2017-08-03T18:19:11.604045Z 3 [Note] (------>MDL PRINT) Mdl duration is:MDL_EXPLICIT 2017-08-03T18:19:11.604073Z 3 [Note] (------->MDL PRINT) Mdl status is:EMPTY 2017-08-03T18:19:11.604133Z 3 [Note] (acquire_lock)THIS MDL LOCK acquire ok!
當然要了解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> show slave status \G
*************************** 1. row ***************************
Master_Log_File: binlog.000002
Read_Master_Log_Pos: 5077
Relay_Log_File: test1-relay-bin.000002
Relay_Log_Pos: 2498
Relay_Master_Log_File: binlog.000002
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Exec_Master_Log_Pos: 5077
Relay_Log_Space: 2705
Last_IO_Errno: 0
Last_IO_Error:
Seconds_Behind_Master: 0
Retrieved_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:42-49
Executed_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:1-49
Auto_Position: 1
但是這個時候我們發現mysql.gtid_executed表已經出現了問題如下：
mysql> select * from gtid_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> show binary logs; +---------------+-----------+ | Log_name | File_size | +---------------+-----------+ | binlog.000001 | 9974 | | binlog.000002 | 5121 | | binlog.000003 | 194 | +---------------+-----------+ 3 rows in set (0.01 sec) mysql> purge binary logs to 'binlog.000003'; Query OK, 0 rows affected (0.04 sec) mysql> show binary logs; +---------------+-----------+ | Log_name | File_size | +---------------+-----------+ | binlog.000003 | 194 | +---------------+-----------+ 1 row in set (0.00 sec)
備庫重啟後錯誤重現：
mysql> show slave status \G
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: 192.168.190.62
Master_User: repl
Master_Port: 3308
Connect_Retry: 60
Master_Log_File: binlog.000003
Read_Master_Log_Pos: 194
Relay_Log_File: test1-relay-bin.000005
Relay_Log_Pos: 4
Relay_Master_Log_File: binlog.000003
Slave_IO_Running: No
Slave_SQL_Running: Yes
Exec_Master_Log_Pos: 194
Relay_Log_Space: 194
Last_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.'
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Retrieved_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:42-49
Executed_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:1-32:42-49
Auto_Position: 1
我們發現I/O thread 試圖獲取主庫的33-41的Gtid事物的事物，已經不能獲取，實際上即使能獲取也會造成事物的重新執行，我們看到Executed_Gtid_Set已經出現了兩個連續的區間：
Executed_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:1-32:42-49
五、總結
前文已經描述過mysql.gtid_executed表的作用和其更改時機，如果我們對其有深刻的瞭解這個案例也是很容易分析的，當然解決辦法在第八節主從搭建的步驟中我已經給出了，也就是在搭建完成後進行reset master和set global gtid_pruged兩步重新初始化一下mysql.gtid_executed表。
作者微信：
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/7728585/viewspace-2148843/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- Mysql 5.7 Gtid內部學習(九) 實際案例(一)MySql
- Mysql 5.7 Gtid內部學習(二) Gtid相關內部資料結構MySql資料結構
- Mysql 5.7 Gtid內部學習(一) 導讀MySql
- Mysql 5.7 Gtid內部學習(六) Mysql啟動初始化Gtid模組MySql
- Mysql 5.7 Gtid內部學習(四) mysql.gtid_executed表Previous gtid Event的改變MySql
- Mysql 5.7 Gtid內部學習(八) Gtid帶來的運維改變MySql運維
- Mysql 5.7 Gtid內部學習(五) mysql.gtid_executed表及其他變數更改時機MySql變數
- Mysql 5.7 Gtid內部學習(三) Gtid和Last_commt/sequnce_number的生成時機MySqlAST
- Mysql 5.7 Gtid內部學習(七) 總結binlog_gtid_simple_recovery引數帶來的影響MySql
- MySQL5.7GTID運維實戰MySql運維
- mysql 5.7 GTID主從配置MySql
- MySQL5.7GTID淺析MySql
- MYSQL5.7-GTID概要翻譯MySql
- MySQL 5.7 用mysqldump搭建gtid主從MySql
- MySQL 5.7 用xtrabackup搭建gtid主從MySql
- MySQL 5.7 基於GTID搭建主從複製MySql
- MySQL 5.7基於GTID的主從複製MySql
- MySQL 5.7 使用GTID方式搭建複製環境MySql
- JAVA內部類學習Java
- MySQL 基礎知識梳理學習（四）—-GTIDMySql
- Mysql 5.7儲存過程的學習MySql儲存過程
- mysql學習（二）MySql
- mysql學習二MySql
- java內部類案例Java
- MYSQL學習（二） --MYSQL框架MySql框架
- mysql學習4：第二章：mysql安裝啟動和關閉——mysql5.7安裝MySql
- MYSQL5.7 MASTER-SLAVE 線上關閉和啟動GTIDMySqlAST
- MySQL 5.7 學習心得之安全相關特性MySql
- 【MySQL】5.7新特性之二MySql
- 深度學習實現NBA球星顏值打分完整案例（二）深度學習
- Mysql架構與內部模組-第二章MySql架構
- MySQL 5.7傳統複製到GTID線上切換（一主一從）MySql
- 5.7學習進度
- 深入理解MySQL5.7GTID系列（七）binlog_gtid_simple_recovery引數的影響總結MySql
- Redo內部解析（二）
- mysql不是內部命令MySql
- 【MySQL學習】在RHEL7.3上使用yum安裝MySQL5.7MySql
- 國內數一數二的網際網路公司內部面試題庫面試題