操作解析：MySQL如何查看復制信息并排查問題（上）

作者：大U的技術課堂 2017-06-09 20:10:44

開發開發工具

本文梳理了UCloud在運維本公司MySQL高可用產品UDB過程中遇到的復制問題，并總結了當復制發生異常時，排查復制異常的方法。

“復制”作為MySQL原生的數據同步功能，在MySQL高可用架構中起著至關重要的作用。本文梳理了UCloud在運維本公司MySQL高可用產品UDB過程中遇到的復制問題，并總結了當復制發生異常時，排查復制異常的方法。

一、錯誤排查

1. 收集復制信息

在復制發生異常時，首先要分別收集與復制、錯誤相關的信息，主要通過以下手段進行。

1.1 查看show slave status

執行命令“show slave status”查看復制相關信息，主要關注幾條信息：

Master_Log_File: MySQL-bin.000063 
Read_Master_Log_Pos: 282657539

IO線程讀取到主庫的binlog文件名和該binlog中的位置。這兩個字段代表復制過程中binlog由主庫傳輸到備庫的進度。

Relay_Log_File: MySQL-relay.000002 
Relay_Log_Pos: 313885

SQL線程執行到relay log文件名和該relay log中的位置。

Relay_Master_Log_File: MySQL-bin.000002 
Exec_Master_Log_Pos: 316585

SQL線程執行到relay log對應主庫中的binlog文件名和該binlog的位置。

這四個字段代表復制過程中，主庫數據在備庫上重放的進度。

Slave_IO_Running: Yes 
Slave_SQL_Running: No

當前發生問題的是哪個線程?IO線程或者是SQL線程。

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

這兩個字段在開啟GTID后才有意義。分別代表IO線程接收到binlog中的事務對應的GTID和SQL線程執行過的事務對應的GTID。

這里的GTID不會因為復制而發生改變，即主庫GTID對應的事務一定是主庫執行過之后，通過復制發送過來的。備庫GTID對應的事務一定是備庫執行的。

Last_Errno/Last_IO_Errno/Last_SQL_Errno 
Laset_Error/Last_IO_Error/Last_SQL_Error

IO/SQL線程發生錯誤的相關描述

1.2 查看錯誤日志

錯誤日志記錄了mysqld發生的錯誤信息，即復制的錯誤信息，同時也會記錄復制開始和停止的相關信息，記錄位置可以通過如下方式查看:

在error log中，主要關注如下信息。

(1) 開始復制(start slave)

從庫啟動復制時，error log中會記錄復制起始位置，包括IO線程讀取主庫端binlog的起始位置和SQL線程執行的relay log起始位置。同時，error log還會記錄開始復制的具體時間。

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) 停止復制(stop slave)

從庫停止復制時，error log會記錄IO線程停止時讀取到的主庫binlog的位置，以及停止復制的時間。

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) 復制錯誤信息

復制錯誤信息的描述會在show slave status的last_error中展現，但如果錯誤信息較長(尤其是在多線程復制的情況下)，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中看到更完整的信息描述以及發生錯誤的時間。

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 查看二進制日志文件

這里的二進制日志文件包括主庫的binlog和從庫的relay log、binlog。

主庫的binlog是指主庫執行過事務記錄的binlog日志。
從庫的relay log是指從庫接收到主庫的binlog日志。
從庫的binlog是指從庫SQL線程復現relay log后記錄的日志(log-slave-updates開啟)，以及從庫執行過的事務記錄的binlog日志。

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

二進制日志文件可以通過命令“show binlog events”或者工具MySQLbinlog來將binlog日志轉換為可識別的格式。

show binlog events格式如下：

上圖顯示的是ROW格式binlog中記錄的內容，其中包含了一個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的時間

為主庫執行事務的時間，不管從庫的relay log和binlog，時間均為主庫執行事務的時間。

(2) Event的server_id

記錄是執行該事務的數據庫的server_id，可以用來區分這條事務是主庫還是從庫執行的。

(3) Event的end log pos

從庫relay log中end log pos為對應主庫中binlog的該event的真實文件位置。
主庫和從庫的binlog中，的end log pos為該binlog的文件真實位置。

(4) EVENT的at xxx

at xxx代表該event在文件中的真實位置。

對于以上二進制日志文件的內容，我們需要關注的信息包括：

Previous_gtids events記錄了當前binlog之前執行過的所有的gtid信息，用來定位具體的gtid。
GTID event中對應的GTID，與事務是一一對應的，表明該事務是由主庫執行還是由從庫執行的。
當錯誤發生時，事務執行的時間，事務的執行和具體語句。
主庫執行數據庫操作后，將相關日志記錄到主庫的binlog中。備庫的IO線程接收到主庫傳輸的binlog日志后，將這些日志記錄到relay log中，如果備庫開啟了logslaveupdates選項，那么SQL線程在重放relay log過程中，會記錄相關binlog日志。這三個二進制文件日志，執行內容上應該是相同的。

1.4 查看其他變量

查看其他復制相關的系統變量或者狀態，如：

執行“show variables like‘gtid_mode’”查看gtid是否開啟;
執行“show status like ‘Rplsemisyncmasterstatus’”查看半同步復制的狀態。

這里不再一一列舉。

2. 排查錯誤

在收集到以上復制信息后，主要通過如下手段排查復制錯誤：

2.1 查看show slave status

查看是哪個線程(IO線程或者SQL線程)發生錯誤，查看錯誤原因。

如果是IO線程發生錯誤，記錄發生錯誤時接收到的binlog文件名和位置(如果開啟了GTID則記錄GTID);
如果是SQL線程發生錯誤，記錄發生錯誤時執行到的relay log文件名和位置(如果開啟了GTID則記錄GTID)。

2.2 查看錯誤日志

進一步確認發生錯誤的原因，部分原因只會記錄在錯誤日志中，不會在show slave status中展示。比如，空間不足導致IO線程出錯、網絡中斷導致IO線程異常等。

查看是不是由于其他用戶正常關閉復制或者kill復制相關的線程導致復制不可用。

查看發生錯誤時，是否為剛剛啟動復制、發生錯誤的語句，是否為***條復制執行的語句。如果為***條語句，則需要考慮是否由于搭建復制錯誤的原因導致復制異常，是否由于意外宕機等其他因素導致復制相關二進制日志文件不正確。

對比主庫和備庫的錯誤日志，查看是否均發生了同樣的復制錯誤，是否主庫做了特殊的錯誤處理。

2.3 對比二進制日志文件

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

如果開啟了GTID，查看備庫是否本身執行了數據庫操而產生了GTID，還要查看備庫執行過的GTID是否要多于主庫，備庫是否執行過其他主機的GTID。

根據發生錯誤時的binlog文件和位置(或者GTID)，解析主庫和備庫的二進制文件，對比相同的文件和位置(或者相同的GTID)時日志中記錄的操作是否相同。

查看備庫的二進制文件，備庫是否執行過與主庫沖突的操作。

二、總結

對于處于正常狀態的復制，應是以下狀態：

查看復制狀態應該是正常狀態，如show slave status顯示IO線程和SQL線程的運行狀態均為YES，如半同步復制中show status like “rpl%”顯示的半同步復制狀態為ON。
主庫和備庫均沒有復制相關的錯誤信息報出。
主庫和備庫的二進制日志文件中記錄的數據庫操作內容應一致，主庫和備庫中的數據內容應保持一致。通過對比分析上述信息，查看異常的狀態或者日志，可以為我們排查復制相關的錯誤提供更多的幫助。

三、版本和配置

總體來說，版本和配置不同只是會造成各種信息的顯示格式不同，并不會對上述方法造成過多影響。

1. 版本

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

MySQL-5.6版本與MySQL-5.7版本在復制相關信息上存在以下差異：

日志：在MySQL-5.6在停止復制時，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

GTID：MySQL-5.6的gtid_executed以global system variables方式展現，MySQL-5.7是以MySQL.gtid_executed表的方式展現。
BINLOG：MySQL-5.6版本在使用自增ID時，會使用如下event來記錄自增ID

#170419 11:27:12 server id 30061  end_log_pos 494 CRC32 0x7a9f75c6      Intvar 
SET INSERT_ID=1/*!*/;

2. 配置

主要體現差異的配置包括gtidmode和binlogformat。

(1) gtid_mode

當gtid開啟時，gtid作為判斷事務由誰執行，是否執行過、事務接收和執行進度的標準。同時,可以通過show slave status直觀看出gtid的接收、執行情況。

當gtid關閉時，file和pos作為接收和執行的判斷標準，serverid作為事務由誰執行的標準。但是事務對應的所有的serverid并沒有完全的展現出來，所以對于我們排查問題，造成一定的困難。

(2) binlog_format

binlog_format影響的是記錄到binlog中日志內容的格式，以同一條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

【本文是51CTO專欄機構作者“大U的技術課堂”的原創文章，轉載請通過微信公眾號(ucloud2012)聯系作者】

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

責任編輯：趙寧寧來源： 51CTO專欄

MySQL 復制線程