操作解析:MySQL如何查看復(fù)制信息并排查問題(下)
“復(fù)制”作為MySQL原生的數(shù)據(jù)同步功能,在MySQL高可用架構(gòu)中起著至關(guān)重要的作用。本文梳理了UCloud在運(yùn)維本公司MySQL高可用產(chǎn)品UDB過程中遇到的復(fù)制問題,并總結(jié)了當(dāng)復(fù)制發(fā)生異常時(shí),排查復(fù)制異常的方法。
本文承接上一篇文章,通過收集到的相關(guān)復(fù)制信息和錯(cuò)誤信息,針對(duì)幾種常見的復(fù)制錯(cuò)誤進(jìn)行分析。
一、常見復(fù)制錯(cuò)誤原因及分析過程
在收集到上述復(fù)制相關(guān)信息和錯(cuò)誤信息后,需要根據(jù)實(shí)際的誤信息進(jìn)行分析,這里羅列了幾種常見的復(fù)制錯(cuò)誤,可以通過部分或者全部在前述章節(jié)收集的相關(guān)信息,分析出復(fù)制錯(cuò)誤發(fā)生原因。
1. 從庫執(zhí)行語句與主庫沖突
1.1 錯(cuò)誤原因
從庫執(zhí)行DML語句或者DDL語句后,主庫和從庫會(huì)出現(xiàn)數(shù)據(jù)不一致的情況,從而導(dǎo)致主庫執(zhí)行的語句在從庫沒有辦法正常執(zhí)行。
1.2 錯(cuò)誤信息
由于從庫執(zhí)行與主庫沖突的語句而導(dǎo)致復(fù)制錯(cuò)誤,常見錯(cuò)誤信息如下:
- 創(chuàng)建庫或者表失敗
- 017-04-18T07:52:40.440723Z 6 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:2' at master log binlog001.000001, end_log_pos 493; Error 'Can't create database 'mydb4'; database exists' on query. Default database: 'mydb4'. Query: 'create database mydb4', Error_code: 1007
- 2017-04-18T07:57:35.975310Z 10 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 378; Could not execute Write_rows event on table mydb.test; Duplicate entry '10' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 378, Error_code: 1062
- [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 506; Could not execute Delete_rows event on table mydb.I1; Can't find record in 'I1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 506, Error_code: 1032
由于這是比較常見的原因,所有導(dǎo)致主從沖突的操作均會(huì)導(dǎo)致復(fù)制出錯(cuò),這里不再一一列舉。
1.3 原因分析過程
這里以“由于數(shù)據(jù)庫存在而導(dǎo)致創(chuàng)建數(shù)據(jù)庫出錯(cuò)”為例來分析原因。
(1) 查看 error log
Error log中顯示的詳細(xì)錯(cuò)誤信息如下:
- 2017-04-18T08:22:26.885713Z 16 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6' at master log binlog001.000001, end_log_pos 1710; Error 'Can't create database 'mydb10'; database exists' on query. Default database: 'mydb10'. Query: 'create database mydb10', Error_code: 1007
顯示在執(zhí)行GTID 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6時(shí)失敗。錯(cuò)誤原因在于數(shù)據(jù)庫已經(jīng)存在,無法創(chuàng)建。
(2) 查看 show slave status
當(dāng)錯(cuò)誤發(fā)生后,查看show slave status顯示的信息時(shí),會(huì)發(fā)現(xiàn)如下信息:
- Master_UUID: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783
- Retrieved_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5
- Executed_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5,
- 3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1
在Executed_Gtid_Set顯示的信息中,除了Master的UUID對(duì)應(yīng)GTID外,還存在另外一個(gè)GTID,我們可以查看從庫的GTID,執(zhí)行如下語句:
發(fā)現(xiàn)另外的GTID是由從庫執(zhí)行而產(chǎn)生。
(3) 查看從庫binlog日志
從庫binlog日志記錄的是SQL線程復(fù)現(xiàn)的主機(jī)binlog信息或者是從庫本身執(zhí)行事務(wù)的binlog日志。這些事務(wù)可以通過server_id或者GTID來區(qū)分。
這里以創(chuàng)建數(shù)據(jù)庫失敗為例,在從庫binlog中,查找3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1對(duì)應(yīng)的事務(wù),發(fā)現(xiàn)如下信息:
- #170418 16:22:15 server id 30002 end_log_pos 1791 CRC32 0xfa89e69a GTID last_committed=6 sequence_number=7
- SET @@SESSION.GTID_NEXT= '3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1'/*!*/;
- # at 1791
- ……
- create database mydb10
(4) 查看從庫relay log日志
從庫relay log日志記錄的是IO線程從主庫接收到的binlog日志信息,我們查看執(zhí)行失敗的GTID對(duì)應(yīng)的事務(wù)信息:
- #170418 16:22:26 server id 30001 end_log_pos 1610 CRC32 0x27c8228f GTID last_committed=5 sequence_number=6
- SET @@SESSION.GTID_NEXT= '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6'/*!*/;
- # at 519
- ……
- create database mydb10
- /*!*/;
(5) 總結(jié)
最終可以確認(rèn)是由于從庫執(zhí)行了創(chuàng)建數(shù)據(jù)庫語句后,SQL線程再次執(zhí)行創(chuàng)建數(shù)據(jù)庫語句時(shí)發(fā)生復(fù)制失敗的情況。
2. 主庫的binlog丟失
2.1 錯(cuò)誤原因
復(fù)制過程中,由于從庫需要讀取的主庫binlog丟失,從而導(dǎo)致復(fù)制發(fā)生異常。導(dǎo)致主庫binlog丟失的主要原因如下:
- 主庫執(zhí)行reset master命令
- 主庫執(zhí)行purge binary/master logs命令
- 主庫設(shè)置了expire_logs_days,自動(dòng)刪除了binlog
- 主庫的binlog被誤刪除
2.2 錯(cuò)誤信息
如果發(fā)生找不到主機(jī)binlog的情況,從庫error log會(huì)報(bào)出如下錯(cuò)誤:
- 2017-04-18T09:01:42.894612Z 17 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'could not find ne
2.3 原因分析過程
(1) 查看 error log
Error log中顯示的詳細(xì)錯(cuò)誤信息如下:
- 2017-04-18T09:01:42.894612Z 17 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the first event '' at 4, the last event read from './binlog001.000002' at 154, the last byte read from './binlog001.000002' at 154.', Error_code: 1236
錯(cuò)誤信息顯示無法找到對(duì)應(yīng)的binlog文件。
(2) 查看 binlog 日志
查看主庫的binlog日志文件列表,可能會(huì)發(fā)現(xiàn)主庫的binlog變成重新開始記錄:
- -rw-r----- 1 songlei.wang songlei.wang 449 Apr 18 17:01 binlog001.000001
- -rw-r----- 1 songlei.wang songlei.wang 19 Apr 18 17:01 binlog_index001.index
或者需要復(fù)制的binlog已經(jīng)被刪除:
- -rw-r----- 1 songlei.wang songlei.wang 241 Apr 18 17:12 binlog001.000006
- -rw-r----- 1 songlei.wang songlei.wang 1716 Apr 18 17:12 binlog001.000007
- -rw-r----- 1 songlei.wang songlei.wang 194 Apr 18 17:12 binlog001.000008
- -rw-r----- 1 songlei.wang songlei.wang 57 Apr 18 17:12 binlog_index001.index
(3) 總結(jié)
如果binlog重新開始記錄,通常是由于主庫執(zhí)行了reset master命令,導(dǎo)致所有的binlog被刪除。
如果binlog仍然在繼續(xù)記錄,只是從庫需要的binlog被刪除,通常是由于主庫手動(dòng)執(zhí)行了purge binary logs命令,或者日志的保留時(shí)間超過了expire_logs_days設(shè)置的時(shí)間。
3. 從庫沒有執(zhí)行主庫復(fù)制的語句
3.1 錯(cuò)誤原因
復(fù)制過程中,用于主庫執(zhí)行事務(wù)對(duì)應(yīng)的GTID已經(jīng)存在于從庫GTID_EXECUTED中,那么從庫便不會(huì)執(zhí)行這些事務(wù),從而導(dǎo)致主庫和從庫的數(shù)據(jù)不一致。通常有如下情況:
主機(jī)執(zhí)行了reset master(從庫當(dāng)前讀取主機(jī)的第一個(gè)binlog,并不會(huì)因?yàn)閞eset master而導(dǎo)致找不到文件)重做主從,從庫沒有清除從庫的binlog。
3.2 錯(cuò)誤信息
在從庫忽略主機(jī)執(zhí)行事務(wù)的過程中,從庫復(fù)制不會(huì)報(bào)出任何錯(cuò)誤,所以這種復(fù)制的異常容易被忽略,沒有辦法及時(shí)發(fā)現(xiàn)。
由于主庫和從庫的數(shù)據(jù)庫不一致,后續(xù)的DML和DDL操作可能會(huì)發(fā)生執(zhí)行失敗的錯(cuò)誤。
3.3 原因分析過程
這里我們以插入語句找不到對(duì)應(yīng)的表為例。
(1) 查看 error log
Error log中記錄錯(cuò)誤信息:
- 2017-04-18 20:39:01 682 [ERROR] Slave SQL: Error 'Table 'mydb.mytbl2' doesn't exist' on query. Default database: 'mydb'. Query: 'insert into mydb.mytbl4 values (1)', Error_code: 1146
(2) 查看show slave status
show slave status顯示的信息全部正常,無從庫執(zhí)行事務(wù)的binlog產(chǎn)生。這里不排除從庫關(guān)閉binlog執(zhí)行drop table操作的可能。
(3) 查看表
分別在主機(jī)和從庫執(zhí)行命令show create table mydb.mytbl4,發(fā)現(xiàn)從庫上并不存在mydb.mytbl4。
(4) 解析 binlog 日志
解析主機(jī)binlog日志,查看建表的事務(wù)日志:
- #170418 20:50:47 server id 30061 end_log_pos 199 CRC32 0xaaa00818 GTID [commit=yes]
- SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;
- # at 199
- #170418 20:50:47 server id 30061 end_log_pos 319 CRC32 0x06f5789f Query thread_id=3 exec_time=0 error_code=0
- ……
- create table if not exists mydb.mytbl4 (A int)
解析從庫的binlog日志,查找是否存在建表的事務(wù)日志:
- #170418 20:49:49 server id 30061 end_log_pos 199 CRC32 0x3051fade GTID [commit=yes]
- SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;
- # at 199
- #170418 20:49:49 server id 30061 end_log_pos 278 CRC32 0x7156a1c9 Query thread_id=3 exec_time=40 error_code=0
- ……
- BEGIN
- /*!*/;
- # at 278
- #170418 20:49:49 server id 30061 end_log_pos 385 CRC32 0x25560e04 Query thread_id=3 exec_time=40 error_code=0
- use `mydb`/*!*/;
- SET TIMESTAMP=1492519789/*!*/;
- insert into mydb.mytbl values (1)
- /*!*/;
- ……
這時(shí)我們發(fā)現(xiàn)對(duì)于相同的GTID,從庫和主機(jī)執(zhí)行的語句不相同。
(5) 總結(jié)
通過上述分析,我們推斷是從庫并沒有執(zhí)行建表語句,進(jìn)而導(dǎo)致主庫數(shù)據(jù)不一致。
(6) 說明
這種情況MySQL-5.7版本會(huì)在復(fù)制時(shí)有更嚴(yán)格校驗(yàn),如果主機(jī)發(fā)送GTID要少于從庫的GTID,那么會(huì)報(bào)告出如下的錯(cuò)誤:
- Got fatal error 1236 from master when reading data from binary log: 'Slave has more GTIDs than the master has, using the master's SERVER_UUID. This may indicate that the end of the binary log was truncated or that the last binary log file was lost, e.g., after a power or disk failure when sync_binlog != 1. The master may or may not have rolled back transactions that were already replica', Error_code: 1236
但是,即使在5.7版本,如果啟動(dòng)復(fù)制時(shí)(錯(cuò)誤后重新啟動(dòng)),主庫執(zhí)行的GTID超過了從庫,仍然會(huì)報(bào)出同樣的錯(cuò)誤。
4. 主庫執(zhí)行了不進(jìn)行復(fù)制的語句
4.1 錯(cuò)誤原因
主庫上執(zhí)行的操作并不會(huì)寫入binlog,因此這里不考慮主庫主動(dòng)關(guān)閉binlog的情況。
4.2 錯(cuò)誤信息
由于主庫和從庫的數(shù)據(jù)不一致,導(dǎo)致主庫執(zhí)行的操作復(fù)制到從庫后,發(fā)生從庫執(zhí)行失敗的情況。如:
創(chuàng)建FEDERATED引擎的表失?。?/p>
- 2017-01-24T08:04:31.682038Z 3 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '887ca716-e202-11e6-8a82-52540086ae59:7' at master log mysql-bin.000004, end_log_pos 906; Error 'server name: 's' doesn't exist!' on query. Default database: 'mydb'. Query: 'CREATE TABLE `mytbl` (
- `idaction` int(10) unsigned NOT NULL AUTO_INCREMENT,
4.3 原因分析過程
這里以使用CONNECTION創(chuàng)建FEDERATED引擎的表為例。
(1) 查看error log
Error log中記錄錯(cuò)誤信息:
- 2017-01-24T08:04:31.682038Z 3 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '887ca716-e202-11e6-8a82-52540086ae59:7' at master log mysql-bin.000004, end_log_pos 906; Error 'server name: 's' doesn't exist!' on query.
(2) 查看主庫和從庫的server表
- 主庫中server表中存在名字為s的記錄。
- 從庫中不存在名字為s的記錄。
(3) 查看CREATE SERVER文檔說明
文檔中記錄的create server語句并不會(huì)記錄到binlog中,所以導(dǎo)致主庫和從庫的數(shù)據(jù)不一致,復(fù)制無法正常進(jìn)行。
(4) 總結(jié)
對(duì)于不記入binlog的操作,需要主庫和從庫同時(shí)執(zhí)行,以防發(fā)生主庫和從庫不一致的情況。
5. 從庫重復(fù)執(zhí)行relay log的語句(非GTID,非多線程復(fù)制)
5.1 錯(cuò)誤原因
如果物理機(jī)發(fā)生宕機(jī)或者從庫發(fā)生意外中斷,那么可能發(fā)生SQL線程已經(jīng)執(zhí)行過了某一個(gè)relay log中的事務(wù),但是這個(gè)事務(wù)對(duì)應(yīng)文件和位置信息并沒有及時(shí)更新到relay_log.info中的情況。在從庫發(fā)生重啟之后,會(huì)將執(zhí)行過的事務(wù)再次重新執(zhí)行。
5.2 錯(cuò)誤信息
重復(fù)執(zhí)行的事務(wù)包括任何記錄到relay log中的事務(wù),可能出現(xiàn)的錯(cuò)誤信息包括:
- 創(chuàng)建庫或者表失敗
- 2017-04-18T07:52:40.440723Z 6 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:2' at master log binlog001.000001, end_log_pos 493; Error 'Can't create database 'mydb4'; database exists' on query. Default database: 'mydb4'. Query: 'create database mydb4', Error_code: 1007
- 2017-04-18T07:57:35.975310Z 10 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 378; Could not execute Write_rows event on table mydb.test; Duplicate entry '10' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 378, Error_code: 1062
- [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 506; Could not execute Delete_rows event on table mydb.I1; Can't find record in 'I1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 506, Error_code: 1032
由于各種類型的事務(wù)均可能執(zhí)行,這里不再一一列舉。
5.3 原因分析過程
這里以插入語句主鍵沖突為例
(1) 查看error log
Error log中記錄以下報(bào)錯(cuò)信息:
- 2017-04-19T03:02:15.448429Z 4 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'binlog001.000001' at position 403, relay log './relaylog002.000002' position: 616
- 2017-04-19T03:02:15.459468Z 4 [ERROR] Slave SQL for channel '': Could not execute Write_rows event on table mydb.k2; Duplicate entry '101' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log binlog001.000001, end_log_pos 621, Error_code: 1062
- 2017-04-19T03:02:15.459526Z 4 [Warning] Slave: Duplicate entry '101' for key 'PRIMARY' Error_code: 1062
可以看到是SQL線程在啟動(dòng)后執(zhí)行第一個(gè)事務(wù)就發(fā)生主鍵沖突的錯(cuò)誤。
(2) 查看show slave status
show slave status顯示的信息全部正常,無從庫執(zhí)行事務(wù)的binlog產(chǎn)生。
(3) mydb.k2
表中已經(jīng)存在了這條記錄。
(4) mydb.k2
查看從庫的relay log,從復(fù)制的起始位置./relaylog002.000002:616查看:
- #170419 11:00:22 server id 30001 end_log_pos 403 CRC32 0x0ef99927 Xid = 7395
- COMMIT/*!*/;
- # at 616 relay log的文件位置
- #170419 11:00:59 server id 30001 end_log_pos 468 CRC32 0xbd3fd6d7 Anonymous_GTID last_committed=1 sequence_number=2 對(duì)應(yīng)主機(jī)的事務(wù)執(zhí)行的時(shí)間
- SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
- # at 681
- #170419 11:00:59 server id 30001 end_log_pos 536 CRC32 0x484841bd Query thread_id=553 exec_time=0 error_code=0
- SET TIMESTAMP=1492570859/*!*/;
- BEGIN
- /*!*/;
- # at 749
- #170419 11:00:59 server id 30001 end_log_pos 581 CRC32 0x9fd66b9e Table_map: `mydb`.`k2` mapped to number 114
- # at 794
- #170419 11:00:59 server id 30001 end_log_pos 621 CRC32 0x4151da88 Write_rows: table id 114 flags: STMT_END_F
- BINLOG '
- 69L2WBMxdQAALQAAAEUCAAAAAHIAAAAAAAEABG15ZGIAAmsyAAEDAACea9af
- 69L2WB4xdQAAKAAAAG0CAAAAAHIAAAAAAAEAAgAB//5lAAAAiNpRQQ==
- '/*!*/;
- ### INSERT INTO `mydb`.`k2`
- ### SET
- ### @1=101
- # at 834
- #170419 11:00:59 server id 30001 end_log_pos 652 CRC32 0xf876844e Xid = 7396
- COMMIT/*!*/;
查看從庫的binlog:
- #170419 11:00:59 server id 30001 end_log_pos 463 CRC32 0x6ede3a0d Anonymous_GTID last_committed=1 sequence_number=2
- SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
- # at 463
- #170419 11:00:59 server id 30001 end_log_pos 526 CRC32 0x5fac2d32 Query thread_id=553 exec_time=0 error_code=0
- SET TIMESTAMP=1492570859/*!*/;
- BEGIN
- /*!*/;
- # at 526
- #170419 11:00:59 server id 30001 end_log_pos 571 CRC32 0xb51f8ec9 Table_map: `mydb`.`k2` mapped to number 108
- # at 571
- #170419 11:00:59 server id 30001 end_log_pos 611 CRC32 0xfa578a3f Write_rows: table id 108 flags: STMT_END_F
- BINLOG '
- 69L2WBMxdQAALQAAADsCAAAAAGwAAAAAAAEABG15ZGIAAmsyAAEDAADJjh+1
- 69L2WB4xdQAAKAAAAGMCAAAAAGwAAAAAAAEAAgAB//5lAAAAP4pX+g==
- '/*!*/;
- ### INSERT INTO `mydb`.`k2`
- ### SET
- ### @1=101
- # at 611
- #170419 11:00:59 server id 30001 end_log_pos 642 CRC32 0xc3a619a0 Xid = 12
- COMMIT/*!*/;
(5) 總結(jié)
通過分析上述binlog內(nèi)容,relay log中并沒有記錄相同的insert語句,但從庫的binlog顯示已經(jīng)執(zhí)行過該語句,當(dāng)從庫重啟后,試圖再次執(zhí)行相同的insert語句,從而導(dǎo)致插入語句的主鍵沖突。
(6) 說明
如果復(fù)制使用GTID,那么GTID的特性會(huì)使從庫不執(zhí)行相同的語句。
如果在5.7版本使用多線程復(fù)制,那么mts_recovery會(huì)修復(fù)這個(gè)問題。
只有在非多線程復(fù)制、非GTID復(fù)制的情況下才可能出現(xiàn)這個(gè)錯(cuò)誤。
二、總結(jié)
如果復(fù)制發(fā)生了錯(cuò)誤,通過收集上述復(fù)制相關(guān)信息和錯(cuò)誤相關(guān)信息,分析這些信息中與正常復(fù)制異常的地方,便可為排查復(fù)制錯(cuò)誤提供更多的信息。
當(dāng)然,復(fù)制的錯(cuò)誤是多種多樣的,并不是所有的錯(cuò)誤都可以排查到具體原因。很多復(fù)制錯(cuò)誤是較難或者無法進(jìn)行排查的,比如主庫或者從庫的binlog日志文件已經(jīng)丟失、關(guān)閉binlog后執(zhí)行某些操作導(dǎo)致復(fù)制不一致,又或者某些內(nèi)核BUG導(dǎo)致MySQL的復(fù)制邏輯本身發(fā)生了異常等。
【本文是51CTO專欄機(jī)構(gòu)作者“大U的技術(shù)課堂”的原創(chuàng)文章,轉(zhuǎn)載請(qǐng)通過微信公眾號(hào)(ucloud2012)聯(lián)系作者】