“復(fù)制”作為MySQL原生的數(shù)據(jù)同步功能，在MySQL高可用架構(gòu)中起著至關(guān)重要的作用。本文梳理了UCloud在運(yùn)維本公司MySQL高可用產(chǎn)品UDB過(guò)程中遇到的復(fù)制問(wèn)題，并總結(jié)了當(dāng)復(fù)制發(fā)生異常時(shí)，排查復(fù)制異常的方法。

一、錯(cuò)誤排查

1. 收集復(fù)制信息

在復(fù)制發(fā)生異常時(shí)，首先要分別收集與復(fù)制、錯(cuò)誤相關(guān)的信息，主要通過(guò)以下手段進(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線程讀取到主庫(kù)的binlog文件名和該binlog中的位置。這兩個(gè)字段代表復(fù)制過(guò)程中binlog由主庫(kù)傳輸?shù)絺鋷?kù)的進(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對(duì)應(yīng)主庫(kù)中的binlog文件名和該binlog的位置。

這四個(gè)字段代表復(fù)制過(guò)程中，主庫(kù)數(shù)據(jù)在備庫(kù)上重放的進(jìn)度。

Slave_IO_Running: Yes 
Slave_SQL_Running: No 

當(dāng)前發(fā)生問(wèn)題的是哪個(gè)線程?IO線程或者是SQL線程。

Retrieved_Gtid_Set: ed7c5ee4-762d-11e6-ab9e-6c92bf24c36a:14-3920163 
Executed_Gtid_Set: 04ffb4f5-762e-11e6-81e4-6c92bf26c5c2:1 

這兩個(gè)字段在開(kāi)啟GTID后才有意義。分別代表IO線程接收到binlog中的事務(wù)對(duì)應(yīng)的GTID和SQL線程執(zhí)行過(guò)的事務(wù)對(duì)應(yīng)的GTID。

這里的GTID不會(huì)因?yàn)閺?fù)制而發(fā)生改變，即主庫(kù)GTID對(duì)應(yīng)的事務(wù)一定是主庫(kù)執(zhí)行過(guò)之后，通過(guò)復(fù)制發(fā)送過(guò)來(lái)的。備庫(kù)GTID對(duì)應(yīng)的事務(wù)一定是備庫(kù)執(zhí)行的。

Last_Errno/Last_IO_Errno/Last_SQL_Errno 
Laset_Error/Last_IO_Error/Last_SQL_Error 

IO/SQL線程發(fā)生錯(cuò)誤的相關(guān)描述

1.2 查看錯(cuò)誤日志

錯(cuò)誤日志記錄了mysqld發(fā)生的錯(cuò)誤信息，即復(fù)制的錯(cuò)誤信息，同時(shí)也會(huì)記錄復(fù)制開(kāi)始和停止的相關(guān)信息，記錄位置可以通過(guò)如下方式查看:

在error log中，主要關(guān)注如下信息。

(1) 開(kāi)始復(fù)制(start slave)

從庫(kù)啟動(dòng)復(fù)制時(shí)，error log中會(huì)記錄復(fù)制起始位置，包括IO線程讀取主庫(kù)端binlog的起始位置和SQL線程執(zhí)行的relay log起始位置。同時(shí)，error log還會(huì)記錄開(kāi)始復(fù)制的具體時(shí)間。

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)

從庫(kù)停止復(fù)制時(shí)，error log會(huì)記錄IO線程停止時(shí)讀取到的主庫(kù)binlog的位置，以及停止復(fù)制的時(shí)間。

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ù)制錯(cuò)誤信息

復(fù)制錯(cuò)誤信息的描述會(huì)在show slave status的last_error中展現(xiàn)，但如果錯(cuò)誤信息較長(zhǎng)(尤其是在多線程復(fù)制的情況下)，show slave status并不能完全顯示錯(cuò)誤的全部信息，需要查看錯(cuò)誤日志才能查看到完整的錯(cuò)誤信息。比如：

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 

上述錯(cuò)誤信息并不是一個(gè)完整的錯(cuò)誤信息描述，不過(guò)可以在error log中看到更完整的信息描述以及發(fā)生錯(cuò)誤的時(shí)間。

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)制日志文件包括主庫(kù)的binlog和從庫(kù)的relay log、binlog。

• 主庫(kù)的binlog是指主庫(kù)執(zhí)行過(guò)事務(wù)記錄的binlog日志。
• 從庫(kù)的relay log是指從庫(kù)接收到主庫(kù)的binlog日志。
• 從庫(kù)的binlog是指從庫(kù)SQL線程復(fù)現(xiàn)relay log后記錄的日志(log-slave-updates開(kāi)啟)，以及從庫(kù)執(zhí)行過(guò)的事務(wù)記錄的binlog日志。

二進(jìn)制日志文件中記錄的日志是以event為單位進(jìn)行，比如一個(gè)DML語(yǔ)句通常由4-5個(gè)event組成，一個(gè)DDL語(yǔ)句通常由2個(gè)event組成。

二進(jìn)制日志文件可以通過(guò)命令“show binlog events”或者工具M(jìn)ySQLbinlog來(lái)將binlog日志轉(zhuǎn)換為可識(shí)別的格式。

show binlog events格式如下：

上圖顯示的是ROW格式binlog中記錄的內(nèi)容，其中包含了一個(gè)DML語(yǔ)句和一條DDL語(yǔ)句。DML語(yǔ)句包含了GTID、QUERY、TABLEMAP、WRITEROW、XID五個(gè)event，DDL語(yǔ)句包含了GTID、QUERY兩個(gè)event。

MySQLbinlog工具同樣可以解析binlog，提供與show binlog event類(lèi)似的event信息，以其中一個(gè)event為例來(lái)說(shuō)明：

#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的時(shí)間

• 為主庫(kù)執(zhí)行事務(wù)的時(shí)間，不管從庫(kù)的relay log和binlog，時(shí)間均為主庫(kù)執(zhí)行事務(wù)的時(shí)間。

(2) Event的server_id

• 記錄是執(zhí)行該事務(wù)的數(shù)據(jù)庫(kù)的server_id，可以用來(lái)區(qū)分這條事務(wù)是主庫(kù)還是從庫(kù)執(zhí)行的。

(3) Event的end log pos

• 從庫(kù)relay log中end log pos為對(duì)應(yīng)主庫(kù)中binlog的該event的真實(shí)文件位置。
• 主庫(kù)和從庫(kù)的binlog中，的end log pos為該binlog的文件真實(shí)位置。

(4) EVENT的at xxx

• at xxx代表該event在文件中的真實(shí)位置。

對(duì)于以上二進(jìn)制日志文件的內(nèi)容，我們需要關(guān)注的信息包括：

• Previous_gtids events記錄了當(dāng)前binlog之前執(zhí)行過(guò)的所有的gtid信息，用來(lái)定位具體的gtid。
• GTID event中對(duì)應(yīng)的GTID，與事務(wù)是一一對(duì)應(yīng)的，表明該事務(wù)是由主庫(kù)執(zhí)行還是由從庫(kù)執(zhí)行的。
• 當(dāng)錯(cuò)誤發(fā)生時(shí)，事務(wù)執(zhí)行的時(shí)間，事務(wù)的執(zhí)行和具體語(yǔ)句。
• 主庫(kù)執(zhí)行數(shù)據(jù)庫(kù)操作后，將相關(guān)日志記錄到主庫(kù)的binlog中。備庫(kù)的IO線程接收到主庫(kù)傳輸?shù)腷inlog日志后，將這些日志記錄到relay log中，如果備庫(kù)開(kāi)啟了logslaveupdates選項(xiàng)，那么SQL線程在重放relay log過(guò)程中，會(huì)記錄相關(guān)binlog日志。這三個(gè)二進(jìn)制文件日志，執(zhí)行內(nèi)容上應(yīng)該是相同的。

1.4 查看其他變量

查看其他復(fù)制相關(guān)的系統(tǒng)變量或者狀態(tài)，如：

• 執(zhí)行“show variables like‘gtid_mode’”查看gtid是否開(kāi)啟;
• 執(zhí)行“show status like ‘Rplsemisyncmasterstatus’”查看半同步復(fù)制的狀態(tài)。

這里不再一一列舉。

2. 排查錯(cuò)誤

在收集到以上復(fù)制信息后，主要通過(guò)如下手段排查復(fù)制錯(cuò)誤：

2.1 查看show slave status

查看是哪個(gè)線程(IO線程或者SQL線程)發(fā)生錯(cuò)誤，查看錯(cuò)誤原因。

• 如果是IO線程發(fā)生錯(cuò)誤，記錄發(fā)生錯(cuò)誤時(shí)接收到的binlog文件名和位置(如果開(kāi)啟了GTID則記錄GTID);
• 如果是SQL線程發(fā)生錯(cuò)誤，記錄發(fā)生錯(cuò)誤時(shí)執(zhí)行到的relay log文件名和位置(如果開(kāi)啟了GTID則記錄GTID)。

2.2 查看錯(cuò)誤日志

進(jìn)一步確認(rèn)發(fā)生錯(cuò)誤的原因，部分原因只會(huì)記錄在錯(cuò)誤日志中，不會(huì)在show slave status中展示。比如，空間不足導(dǎo)致IO線程出錯(cuò)、網(wǎng)絡(luò)中斷導(dǎo)致IO線程異常等。

查看是不是由于其他用戶正常關(guān)閉復(fù)制或者kill復(fù)制相關(guān)的線程導(dǎo)致復(fù)制不可用。

查看發(fā)生錯(cuò)誤時(shí)，是否為剛剛啟動(dòng)復(fù)制、發(fā)生錯(cuò)誤的語(yǔ)句，是否為***條復(fù)制執(zhí)行的語(yǔ)句。如果為***條語(yǔ)句，則需要考慮是否由于搭建復(fù)制錯(cuò)誤的原因?qū)е聫?fù)制異常，是否由于意外宕機(jī)等其他因素導(dǎo)致復(fù)制相關(guān)二進(jìn)制日志文件不正確。

對(duì)比主庫(kù)和備庫(kù)的錯(cuò)誤日志，查看是否均發(fā)生了同樣的復(fù)制錯(cuò)誤，是否主庫(kù)做了特殊的錯(cuò)誤處理。

2.3 對(duì)比二進(jìn)制日志文件

對(duì)比備庫(kù)正在接收的binlog與主庫(kù)正在執(zhí)行的binlog是否存在沖突(備庫(kù)接收的binlog文件和位置要大于主庫(kù)執(zhí)行的)。

如果開(kāi)啟了GTID，查看備庫(kù)是否本身執(zhí)行了數(shù)據(jù)庫(kù)操而產(chǎn)生了GTID，還要查看備庫(kù)執(zhí)行過(guò)的GTID是否要多于主庫(kù)，備庫(kù)是否執(zhí)行過(guò)其他主機(jī)的GTID。

根據(jù)發(fā)生錯(cuò)誤時(shí)的binlog文件和位置(或者GTID)，解析主庫(kù)和備庫(kù)的二進(jìn)制文件，對(duì)比相同的文件和位置(或者相同的GTID)時(shí)日志中記錄的操作是否相同。

查看備庫(kù)的二進(jìn)制文件，備庫(kù)是否執(zhí)行過(guò)與主庫(kù)沖突的操作。

二、總結(jié)

對(duì)于處于正常狀態(tài)的復(fù)制，應(yīng)是以下?tīng)顟B(tài)：

• 查看復(fù)制狀態(tài)應(yīng)該是正常狀態(tài)，如show slave status顯示IO線程和SQL線程的運(yùn)行狀態(tài)均為YES，如半同步復(fù)制中show status like “rpl%”顯示的半同步復(fù)制狀態(tài)為ON。
• 主庫(kù)和備庫(kù)均沒(méi)有復(fù)制相關(guān)的錯(cuò)誤信息報(bào)出。
• 主庫(kù)和備庫(kù)的二進(jìn)制日志文件中記錄的數(shù)據(jù)庫(kù)操作內(nèi)容應(yīng)一致，主庫(kù)和備庫(kù)中的數(shù)據(jù)內(nèi)容應(yīng)保持一致。 通過(guò)對(duì)比分析上述信息，查看異常的狀態(tài)或者日志，可以為我們排查復(fù)制相關(guān)的錯(cuò)誤提供更多的幫助。

三、版本和配置

總體來(lái)說(shuō)，版本和配置不同只是會(huì)造成各種信息的顯示格式不同，并不會(huì)對(duì)上述方法造成過(guò)多影響。

1. 版本

上述信息收集和分析的舉例均是在MySQL-5.7版本上進(jìn)行的，不同大版本在信息的內(nèi)容或者信息的存放方式上可能存在一定差異。

MySQL-5.6版本與MySQL-5.7版本在復(fù)制相關(guān)信息上存在以下差異：

• 日志：在MySQL-5.6在停止復(fù)制時(shí)，error log會(huì)有錯(cuò)誤的信息記錄：

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 

• GTID：MySQL-5.6的gtid_executed以global system variables方式展現(xiàn)，MySQL-5.7是以MySQL.gtid_executed表的方式展現(xiàn)。
• BINLOG：MySQL-5.6版本在使用自增ID時(shí)，會(huì)使用如下event來(lái)記錄自增ID

#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開(kāi)啟時(shí)，gtid作為判斷事務(wù)由誰(shuí)執(zhí)行，是否執(zhí)行過(guò)、事務(wù)接收和執(zhí)行進(jìn)度的標(biāo)準(zhǔn)。同時(shí),可以通過(guò)show slave status直觀看出gtid的接收、執(zhí)行情況。

當(dāng)gtid關(guān)閉時(shí)，file和pos作為接收和執(zhí)行的判斷標(biāo)準(zhǔn)，serverid作為事務(wù)由誰(shuí)執(zhí)行的標(biāo)準(zhǔn)。但是事務(wù)對(duì)應(yīng)的所有的serverid并沒(méi)有完全的展現(xiàn)出來(lái)，所以對(duì)于我們排查問(wèn)題，造成一定的困難。

(2) binlog_format

binlog_format影響的是記錄到binlog中日志內(nèi)容的格式，以同一條INSERT語(yǔ)句為例，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 

【本文是51CTO專欄機(jī)構(gòu)作者“大U的技術(shù)課堂”的原創(chuàng)文章，轉(zhuǎn)載請(qǐng)通過(guò)微信公眾號(hào)(ucloud2012)聯(lián)系作者】

 戳這里，看該作者更多好文