建站
咨詢
售后
建站咨詢
新聞中心
“復(fù)制”作為MySQL原生的數(shù)據(jù)同步功能，在MySQL高可用架構(gòu)中起著至關(guān)重要的作用。本文梳理了UCloud在運維本公司MySQL高可用產(chǎn)品UDB過程中遇到的復(fù)制問題，并總結(jié)了當(dāng)復(fù)制發(fā)生異常時，排查復(fù)制異常的方法。
一、錯誤排查
1. 收集復(fù)制信息
在復(fù)制發(fā)生異常時，首先要分別收集與復(fù)制、錯誤相關(guān)的信息，主要通過以下手段進(jìn)行。
1.1 查看show slave status
執(zhí)行命令“show slave status”查看復(fù)制相關(guān)信息，主要關(guān)注幾條信息：
- Master_Log_File: MySQL-bin.000063
- Read_Master_Log_Pos: 282657539
IO線程讀取到主庫的binlog文件名和該binlog中的位置。這兩個字段代表復(fù)制過程中binlog由主庫傳輸?shù)絺鋷斓倪M(jìn)度。
- Relay_Log_File: MySQL-relay.000002
- Relay_Log_Pos: 313885
SQL線程執(zhí)行到relay log文件名和該relay log中的位置。
- Relay_Master_Log_File: MySQL-bin.000002
- Exec_Master_Log_Pos: 316585
SQL線程執(zhí)行到relay log對應(yīng)主庫中的binlog文件名和該binlog的位置。
這四個字段代表復(fù)制過程中，主庫數(shù)據(jù)在備庫上重放的進(jìn)度。
- Slave_IO_Running: Yes
- Slave_SQL_Running: No
當(dāng)前發(fā)生問題的是哪個線程?IO線程或者是SQL線程。
- Retrieved_Gtid_Set: ed7c5ee4-762d-11e6-ab9e-6c92bf24c36a:14-3920163
- Executed_Gtid_Set: 04ffb4f5-762e-11e6-81e4-6c92bf26c5c2:1
這兩個字段在開啟GTID后才有意義。分別代表IO線程接收到binlog中的事務(wù)對應(yīng)的GTID和SQL線程執(zhí)行過的事務(wù)對應(yīng)的GTID。
這里的GTID不會因為復(fù)制而發(fā)生改變，即主庫GTID對應(yīng)的事務(wù)一定是主庫執(zhí)行過之后，通過復(fù)制發(fā)送過來的。備庫GTID對應(yīng)的事務(wù)一定是備庫執(zhí)行的。
- Last_Errno/Last_IO_Errno/Last_SQL_Errno
- Laset_Error/Last_IO_Error/Last_SQL_Error
IO/SQL線程發(fā)生錯誤的相關(guān)描述
1.2 查看錯誤日志
錯誤日志記錄了mysqld發(fā)生的錯誤信息，即復(fù)制的錯誤信息，同時也會記錄復(fù)制開始和停止的相關(guān)信息，記錄位置可以通過如下方式查看:
在error log中，主要關(guān)注如下信息。
(1) 開始復(fù)制(start slave)
從庫啟動復(fù)制時，error log中會記錄復(fù)制起始位置，包括IO線程讀取主庫端binlog的起始位置和SQL線程執(zhí)行的relay log起始位置。同時，error log還會記錄開始復(fù)制的具體時間。
- 2017-04-17T14:47:19.691088Z 7 [Note] Slave I/O thread for channel '': connected to master
- 'repl@192.168.150.21:30001',replication started in log
- 'binlog001.000002' at position 194
- 2017-04-17T14:47:19.693377Z 8 [Note] Slave SQL thread for channel '' initialized, starting replication in log
- 'binlog001.000002' at position 194, relay log
- './relaylog002.000217' position: 407
(2) 停止復(fù)制(stop slave)
從庫停止復(fù)制時，error log會記錄IO線程停止時讀取到的主庫binlog的位置，以及停止復(fù)制的時間。
- 2017-04-18T03:05:52.920750Z 14 [Note] Error reading relay log event for channel '': slave SQL thread was killed2017-04-18T03:05:52.922007Z 13 [Note] Slave I/O thread killed while reading event for channel ''2017-04-18T03:05:52.922041Z 13 [Note] Slave I/O thread exiting for channel '', read up to log 'binlog001.000002', position 443
(3) 復(fù)制錯誤信息
復(fù)制錯誤信息的描述會在show slave status的last_error中展現(xiàn)，但如果錯誤信息較長(尤其是在多線程復(fù)制的情況下)，show slave status并不能完全顯示錯誤的全部信息，需要查看錯誤日志才能查看到完整的錯誤信息。比如：
- Last_Errno: 1007
- Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:4' at master log binlog001.000002, end_log_pos 605. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
- Skip_Counter: 0
上述錯誤信息并不是一個完整的錯誤信息描述，不過可以在error log中看到更完整的信息描述以及發(fā)生錯誤的時間。
- 2017-04-18T03:19:00.037806Z 23 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:4' at master log binlog001.000002, end_log_pos 605; Error 'Can't create database 'mydb3'; database exists' on query. Default database: 'mydb3'. Query: 'create database mydb3', Error_code: 1007
1.3 查看二進(jìn)制日志文件
這里的二進(jìn)制日志文件包括主庫的binlog和從庫的relay log、binlog。
- 主庫的binlog是指主庫執(zhí)行過事務(wù)記錄的binlog日志。
- 從庫的relay log是指從庫接收到主庫的binlog日志。
- 從庫的binlog是指從庫SQL線程復(fù)現(xiàn)relay log后記錄的日志(log-slave-updates開啟)，以及從庫執(zhí)行過的事務(wù)記錄的binlog日志。
二進(jìn)制日志文件中記錄的日志是以event為單位進(jìn)行，比如一個DML語句通常由4-5個event組成，一個DDL語句通常由2個event組成。
二進(jìn)制日志文件可以通過命令“show binlog events”或者工具M(jìn)ySQLbinlog來將binlog日志轉(zhuǎn)換為可識別的格式。
show binlog events格式如下：
上圖顯示的是ROW格式binlog中記錄的內(nèi)容，其中包含了一個DML語句和一條DDL語句。DML語句包含了GTID、QUERY、TABLEMAP、WRITEROW、XID五個event，DDL語句包含了GTID、QUERY兩個event。
MySQLbinlog工具同樣可以解析binlog，提供與show binlog event類似的event信息，以其中一個event為例來說明：
- #170417 23:18:37 server id 30001 end_log_pos 412 CRC32 0x818b4058 Write_rows: table id 110 flags: STMT_END_F
- BINLOG '
- zdz0WBMxdQAALQAAAHQBAAAAAG4AAAAAAAEABG15ZGIAAkkxAAEDAAF0sqv/
- zdz0WB4xdQAAKAAAAJwBAAAAAG4AAAAAAAEAAgAB//4KGgAAWECLgQ==
- '/*!*/;
- ### INSERT INTO `mydb`.`I1`
- ### SET
- ### @1=6666
- # at 412
(1) Event的時間
- 為主庫執(zhí)行事務(wù)的時間，不管從庫的relay log和binlog，時間均為主庫執(zhí)行事務(wù)的時間。
(2) Event的server_id
- 記錄是執(zhí)行該事務(wù)的數(shù)據(jù)庫的server_id，可以用來區(qū)分這條事務(wù)是主庫還是從庫執(zhí)行的。
(3) Event的end log pos
- 從庫relay log中end log pos為對應(yīng)主庫中binlog的該event的真實文件位置。
- 主庫和從庫的binlog中，的end log pos為該binlog的文件真實位置。
(4) EVENT的at xxx
- at xxx代表該event在文件中的真實位置。
對于以上二進(jìn)制日志文件的內(nèi)容，我們需要關(guān)注的信息包括：
- Previous_gtids events記錄了當(dāng)前binlog之前執(zhí)行過的所有的gtid信息，用來定位具體的gtid。
- GTID event中對應(yīng)的GTID，與事務(wù)是一一對應(yīng)的，表明該事務(wù)是由主庫執(zhí)行還是由從庫執(zhí)行的。
- 當(dāng)錯誤發(fā)生時，事務(wù)執(zhí)行的時間，事務(wù)的執(zhí)行和具體語句。
- 主庫執(zhí)行數(shù)據(jù)庫操作后，將相關(guān)日志記錄到主庫的binlog中。備庫的IO線程接收到主庫傳輸?shù)腷inlog日志后，將這些日志記錄到relay log中，如果備庫開啟了logslaveupdates選項，那么SQL線程在重放relay log過程中，會記錄相關(guān)binlog日志。這三個二進(jìn)制文件日志，執(zhí)行內(nèi)容上應(yīng)該是相同的。
1.4 查看其他變量
查看其他復(fù)制相關(guān)的系統(tǒng)變量或者狀態(tài)，如：
- 執(zhí)行“show variables like‘gtid_mode’”查看gtid是否開啟;
- 執(zhí)行“show status like ‘Rplsemisyncmasterstatus’”查看半同步復(fù)制的狀態(tài)。
這里不再一一列舉。
2. 排查錯誤
在收集到以上復(fù)制信息后，主要通過如下手段排查復(fù)制錯誤：
2.1 查看show slave status
查看是哪個線程(IO線程或者SQL線程)發(fā)生錯誤，查看錯誤原因。
- 如果是IO線程發(fā)生錯誤，記錄發(fā)生錯誤時接收到的binlog文件名和位置(如果開啟了GTID則記錄GTID);
- 如果是SQL線程發(fā)生錯誤，記錄發(fā)生錯誤時執(zhí)行到的relay log文件名和位置(如果開啟了GTID則記錄GTID)。
2.2 查看錯誤日志
進(jìn)一步確認(rèn)發(fā)生錯誤的原因，部分原因只會記錄在錯誤日志中，不會在show slave status中展示。比如，空間不足導(dǎo)致IO線程出錯、網(wǎng)絡(luò)中斷導(dǎo)致IO線程異常等。
查看是不是由于其他用戶正常關(guān)閉復(fù)制或者kill復(fù)制相關(guān)的線程導(dǎo)致復(fù)制不可用。
查看發(fā)生錯誤時，是否為剛剛啟動復(fù)制、發(fā)生錯誤的語句，是否為***條復(fù)制執(zhí)行的語句。如果為***條語句，則需要考慮是否由于搭建復(fù)制錯誤的原因?qū)е聫?fù)制異常，是否由于意外宕機等其他因素導(dǎo)致復(fù)制相關(guān)二進(jìn)制日志文件不正確。
對比主庫和備庫的錯誤日志，查看是否均發(fā)生了同樣的復(fù)制錯誤，是否主庫做了特殊的錯誤處理。
2.3 對比二進(jìn)制日志文件
對比備庫正在接收的binlog與主庫正在執(zhí)行的binlog是否存在沖突(備庫接收的binlog文件和位置要大于主庫執(zhí)行的)。
如果開啟了GTID，查看備庫是否本身執(zhí)行了數(shù)據(jù)庫操而產(chǎn)生了GTID，還要查看備庫執(zhí)行過的GTID是否要多于主庫，備庫是否執(zhí)行過其他主機的GTID。
根據(jù)發(fā)生錯誤時的binlog文件和位置(或者GTID)，解析主庫和備庫的二進(jìn)制文件，對比相同的文件和位置(或者相同的GTID)時日志中記錄的操作是否相同。
查看備庫的二進(jìn)制文件，備庫是否執(zhí)行過與主庫沖突的操作。
二、總結(jié)
對于處于正常狀態(tài)的復(fù)制，應(yīng)是以下狀態(tài)：
- 查看復(fù)制狀態(tài)應(yīng)該是正常狀態(tài)，如show slave status顯示IO線程和SQL線程的運行狀態(tài)均為YES，如半同步復(fù)制中show status like “rpl%”顯示的半同步復(fù)制狀態(tài)為ON。
- 主庫和備庫均沒有復(fù)制相關(guān)的錯誤信息報出。
- 主庫和備庫的二進(jìn)制日志文件中記錄的數(shù)據(jù)庫操作內(nèi)容應(yīng)一致，主庫和備庫中的數(shù)據(jù)內(nèi)容應(yīng)保持一致。 通過對比分析上述信息，查看異常的狀態(tài)或者日志，可以為我們排查復(fù)制相關(guān)的錯誤提供更多的幫助。
三、版本和配置
總體來說，版本和配置不同只是會造成各種信息的顯示格式不同，并不會對上述方法造成過多影響。
1. 版本
上述信息收集和分析的舉例均是在MySQL-5.7版本上進(jìn)行的，不同大版本在信息的內(nèi)容或者信息的存放方式上可能存在一定差異。
MySQL-5.6版本與MySQL-5.7版本在復(fù)制相關(guān)信息上存在以下差異：
- 日志：在MySQL-5.6在停止復(fù)制時，error log會有錯誤的信息記錄：
- 2017-04-18 17:32:46 682 [Note] Error reading relay log event: slave SQL thread was killed
- 2017-04-18 17:32:46 682 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
- 2017-04-18 17:32:46 682 [Note] Slave I/O thread killed while reading event
- 2017-04-18 17:32:46 682 [Note] Slave I/O thread exiting, read up to log 'b5620.000004', position 151
- #170419 11:27:12 server id 30061 end_log_pos 494 CRC32 0x7a9f75c6 Intvar
- SET INSERT_ID=1/*!*/;
2. 配置
主要體現(xiàn)差異的配置包括gtidmode和binlogformat。
(1) gtid_mode
當(dāng)gtid開啟時，gtid作為判斷事務(wù)由誰執(zhí)行，是否執(zhí)行過、事務(wù)接收和執(zhí)行進(jìn)度的標(biāo)準(zhǔn)。同時,可以通過show slave status直觀看出gtid的接收、執(zhí)行情況。
當(dāng)gtid關(guān)閉時，file和pos作為接收和執(zhí)行的判斷標(biāo)準(zhǔn)，serverid作為事務(wù)由誰執(zhí)行的標(biāo)準(zhǔn)。但是事務(wù)對應(yīng)的所有的serverid并沒有完全的展現(xiàn)出來，所以對于我們排查問題，造成一定的困難。
(2) binlog_format
binlog_format影響的是記錄到binlog中日志內(nèi)容的格式，以同一條INSERT語句為例，statement格式記錄到binlog中的格式如下(只顯示差異部分)：
- #170418 17:47:06 server id 30001 end_log_pos 730 CRC32 0xdaf9a789 Query thread_id=154 exec_time=0 error_code=0
- SET TIMESTAMP=1492508826/*!*/;
- insert into mydb.m1 values (13)
- /*!*/;
row格式記錄到binlog中的格式如下：
- #170418 17:46:25 server id 30001 end_log_pos 376 CRC32 0xcfdad7cd Table_map: `mydb`.`m1` mapped to number 114
- # at 376
- #170418 17:46:25 server id 30001 end_log_pos 416 CRC32 0xed08eabe Write_rows: table id 114 flags: STMT_END_F
- BINLOG '
- ceD1WBMxdQAALQAAAHgBAAAAAHIAAAAAAAEABG15ZGIAAm0xAAEDAAHN19rP
- ceD1WB4xdQAAKAAAAKABAAAAAHIAAAAAAAEAAgAB//4NAAAAvuoI7Q==
- '/*!*/;
- ### INSERT INTO `mydb`.`m1`
- ### SET
- ### @1=13
- # at 416
【本文是專欄機構(gòu)作者“大U的技術(shù)課堂”的原創(chuàng)文章，轉(zhuǎn)載請通過微信公眾號(ucloud2012)聯(lián)系作者】
戳這里，看該作者更多好文
新聞名稱：操作解析：MySQL如何查看復(fù)制信息并排查問題（上）
文章位置：http://www.5511xx.com/article/dphcejp.html
