操作解析:MySQL如何查看复制信息并排查问题(下)

“复制”作为MySQL原生的数据同步功能,在MySQL高可用架构中起着至关重要的作用。本文梳理了UCloud在运维本公司MySQL高可用产品UDB过程中遇到的复制问题,并总结了当复制发生异常时,排查复制异常的方法。

员工经过长期磨合与沉淀,具备了协作精神,得以通过团队的力量开发出优质的产品。创新互联公司坚持“专注、创新、易用”的产品理念,因为“专注所以专业、创新互联网站所以易用所以简单”。公司专注于为企业提供成都网站建设、成都做网站、微信公众号开发、电商网站开发,小程序开发,软件定制网站建设等一站式互联网企业服务。

本文承接上一篇文章,通过收集到的相关复制信息和错误信息,针对几种常见的复制错误进行分析。

一、常见复制错误原因及分析过程

在收集到上述复制相关信息和错误信息后,需要根据实际的误信息进行分析,这里罗列了几种常见的复制错误,可以通过部分或者全部在前述章节收集的相关信息,分析出复制错误发生原因。

1. 从库执行语句与主库冲突

1.1 错误原因

从库执行DML语句或者DDL语句后,主库和从库会出现数据不一致的情况,从而导致主库执行的语句在从库没有办法正常执行。

1.2 错误信息

由于从库执行与主库冲突的语句而导致复制错误,常见错误信息如下:

  • 创建库或者表失败
  •   
      
      
      
    1. 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
  • 插入语句主键冲突
  •   
      
      
      
    1. 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
  • 删除语句找不到对应的语句
  •   
      
      
      
    1. [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

由于这是比较常见的原因,所有导致主从冲突的操作均会导致复制出错,这里不再一一列举。

1.3 原因分析过程

这里以“由于数据库存在而导致创建数据库出错”为例来分析原因。

(1) 查看 error log

Error log中显示的详细错误信息如下:

 
 
 
 
  1. 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

显示在执行GTID 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6时失败。错误原因在于数据库已经存在,无法创建。

(2) 查看 show slave status

当错误发生后,查看show slave status显示的信息时,会发现如下信息:

 
 
 
 
  1. Master_UUID: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783
  2. Retrieved_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5
  3. Executed_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5,
  4. 3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1

在Executed_Gtid_Set显示的信息中,除了Master的UUID对应GTID外,还存在另外一个GTID,我们可以查看从库的GTID,执行如下语句:

发现另外的GTID是由从库执行而产生。

(3) 查看从库binlog日志

从库binlog日志记录的是SQL线程复现的主机binlog信息或者是从库本身执行事务的binlog日志。这些事务可以通过server_id或者GTID来区分。

这里以创建数据库失败为例,在从库binlog中,查找3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1对应的事务,发现如下信息:

 
 
 
 
  1. #170418 16:22:15 server id 30002  end_log_pos 1791 CRC32 0xfa89e69a     GTID    last_committed=6        sequence_number=7
  2. SET @@SESSION.GTID_NEXT= '3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1'/*!*/;
  3. # at 1791
  4. ……
  5. create database mydb10

(4) 查看从库relay log日志

从库relay log日志记录的是IO线程从主库接收到的binlog日志信息,我们查看执行失败的GTID对应的事务信息:

 
 
 
 
  1. #170418 16:22:26 server id 30001  end_log_pos 1610 CRC32 0x27c8228f     GTID    last_committed=5        sequence_number=6
  2. SET @@SESSION.GTID_NEXT= '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6'/*!*/;
  3. # at 519
  4. ……
  5. create database mydb10
  6. /*!*/;

(5) 总结

最终可以确认是由于从库执行了创建数据库语句后,SQL线程再次执行创建数据库语句时发生复制失败的情况。

2. 主库的binlog丢失

2.1 错误原因

复制过程中,由于从库需要读取的主库binlog丢失,从而导致复制发生异常。导致主库binlog丢失的主要原因如下:

  • 主库执行reset master命令
  • 主库执行purge binary/master logs命令
  • 主库设置了expire_logs_days,自动删除了binlog
  • 主库的binlog被误删除

2.2 错误信息

如果发生找不到主机binlog的情况,从库error log会报出如下错误:

 
 
 
 
  1. 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中显示的详细错误信息如下:

 
 
 
 
  1. 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

错误信息显示无法找到对应的binlog文件。

(2) 查看 binlog 日志

查看主库的binlog日志文件列表,可能会发现主库的binlog变成重新开始记录:

 
 
 
 
  1. -rw-r-----  1 songlei.wang songlei.wang      449 Apr 18 17:01 binlog001.000001
  2. -rw-r-----  1 songlei.wang songlei.wang       19 Apr 18 17:01 binlog_index001.index

或者需要复制的binlog已经被删除:

 
 
 
 
  1. -rw-r-----  1 songlei.wang songlei.wang      241 Apr 18 17:12 binlog001.000006
  2. -rw-r-----  1 songlei.wang songlei.wang     1716 Apr 18 17:12 binlog001.000007
  3. -rw-r-----  1 songlei.wang songlei.wang      194 Apr 18 17:12 binlog001.000008
  4. -rw-r-----  1 songlei.wang songlei.wang       57 Apr 18 17:12 binlog_index001.index

(3) 总结

如果binlog重新开始记录,通常是由于主库执行了reset master命令,导致所有的binlog被删除。

如果binlog仍然在继续记录,只是从库需要的binlog被删除,通常是由于主库手动执行了purge binary logs命令,或者日志的保留时间超过了expire_logs_days设置的时间。

3. 从库没有执行主库复制的语句

3.1 错误原因

复制过程中,用于主库执行事务对应的GTID已经存在于从库GTID_EXECUTED中,那么从库便不会执行这些事务,从而导致主库和从库的数据不一致。通常有如下情况:

主机执行了reset master(从库当前读取主机的第一个binlog,并不会因为reset master而导致找不到文件)重做主从,从库没有清除从库的binlog。

3.2 错误信息

在从库忽略主机执行事务的过程中,从库复制不会报出任何错误,所以这种复制的异常容易被忽略,没有办法及时发现。

由于主库和从库的数据库不一致,后续的DML和DDL操作可能会发生执行失败的错误。

3.3 原因分析过程

这里我们以插入语句找不到对应的表为例。

(1) 查看 error log

Error log中记录错误信息:

 
 
 
 
  1. 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显示的信息全部正常,无从库执行事务的binlog产生。这里不排除从库关闭binlog执行drop table操作的可能。

(3) 查看表

分别在主机和从库执行命令show create table mydb.mytbl4,发现从库上并不存在mydb.mytbl4。

(4) 解析 binlog 日志

解析主机binlog日志,查看建表的事务日志:

 
 
 
 
  1. #170418 20:50:47 server id 30061  end_log_pos 199 CRC32 0xaaa00818      GTID [commit=yes]
  2. SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;
  3. # at 199
  4. #170418 20:50:47 server id 30061  end_log_pos 319 CRC32 0x06f5789f      Query   thread_id=3     exec_time=0     error_code=0
  5. ……
  6. create table if not exists mydb.mytbl4 (A int)

解析从库的binlog日志,查找是否存在建表的事务日志:

 
 
 
 
  1. #170418 20:49:49 server id 30061  end_log_pos 199 CRC32 0x3051fade      GTID [commit=yes]
  2. SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;
  3. # at 199
  4. #170418 20:49:49 server id 30061  end_log_pos 278 CRC32 0x7156a1c9      Query   thread_id=3     exec_time=40    error_code=0
  5. ……
  6. BEGIN
  7. /*!*/;
  8. # at 278
  9. #170418 20:49:49 server id 30061  end_log_pos 385 CRC32 0x25560e04      Query   thread_id=3     exec_time=40    error_code=0
  10. use `mydb`/*!*/;
  11. SET TIMESTAMP=1492519789/*!*/;
  12. insert into mydb.mytbl values (1)
  13. /*!*/;
  14. ……

这时我们发现对于相同的GTID,从库和主机执行的语句不相同。

(5) 总结

通过上述分析,我们推断是从库并没有执行建表语句,进而导致主库数据不一致。

(6) 说明

这种情况MySQL-5.7版本会在复制时有更严格校验,如果主机发送GTID要少于从库的GTID,那么会报告出如下的错误:

 
 
 
 
  1. 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版本,如果启动复制时(错误后重新启动),主库执行的GTID超过了从库,仍然会报出同样的错误。

4. 主库执行了不进行复制的语句

4.1 错误原因

主库上执行的操作并不会写入binlog,因此这里不考虑主库主动关闭binlog的情况。

4.2 错误信息

由于主库和从库的数据不一致,导致主库执行的操作复制到从库后,发生从库执行失败的情况。如:

创建FEDERATED引擎的表失败:

 
 
 
 
  1. 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` (
  2. `idaction` int(10) unsigned NOT NULL AUTO_INCREMENT,

4.3 原因分析过程

这里以使用CONNECTION创建FEDERATED引擎的表为例。

(1) 查看error log

Error log中记录错误信息:

 
 
 
 
  1. 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语句并不会记录到binlog中,所以导致主库和从库的数据不一致,复制无法正常进行。

(4) 总结

对于不记入binlog的操作,需要主库和从库同时执行,以防发生主库和从库不一致的情况。

5. 从库重复执行relay log的语句(非GTID,非多线程复制)

5.1 错误原因

如果物理机发生宕机或者从库发生意外中断,那么可能发生SQL线程已经执行过了某一个relay log中的事务,但是这个事务对应文件和位置信息并没有及时更新到relay_log.info中的情况。在从库发生重启之后,会将执行过的事务再次重新执行。

5.2 错误信息

重复执行的事务包括任何记录到relay log中的事务,可能出现的错误信息包括:

  • 创建库或者表失败
  •   
      
      
      
    1. 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
  • 插入语句主键冲突
  •   
      
      
      
    1. 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
  • 删除语句找不到对应的语句
  •   
      
      
      
    1. [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

由于各种类型的事务均可能执行,这里不再一一列举。

5.3 原因分析过程

这里以插入语句主键冲突为例

(1) 查看error log

Error log中记录以下报错信息:

 
 
 
 
  1. 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
  2. 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
  3. 2017-04-19T03:02:15.459526Z 4 [Warning] Slave: Duplicate entry '101' for key 'PRIMARY' Error_code: 1062

可以看到是SQL线程在启动后执行第一个事务就发生主键冲突的错误。

(2) 查看show slave status

show slave status显示的信息全部正常,无从库执行事务的binlog产生。

(3) mydb.k2

表中已经存在了这条记录。

(4) mydb.k2

查看从库的relay log,从复制的起始位置./relaylog002.000002:616查看:

 
 
 
 
  1. #170419 11:00:22 server id 30001  end_log_pos 403 CRC32 0x0ef99927      Xid = 7395
  2. COMMIT/*!*/;
  3. # at 616                  relay log的文件位置
  4. #170419 11:00:59 server id 30001  end_log_pos 468 CRC32 0xbd3fd6d7      Anonymous_GTID  last_committed=1        sequence_number=2                      对应主机的事务执行的时间
  5. SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
  6. # at 681
  7. #170419 11:00:59 server id 30001  end_log_pos 536 CRC32 0x484841bd      Query   thread_id=553   exec_time=0     error_code=0
  8. SET TIMESTAMP=1492570859/*!*/;
  9. BEGIN
  10. /*!*/;
  11. # at 749
  12. #170419 11:00:59 server id 30001  end_log_pos 581 CRC32 0x9fd66b9e      Table_map: `mydb`.`k2` mapped to number 114
  13. # at 794
  14. #170419 11:00:59 server id 30001  end_log_pos 621 CRC32 0x4151da88      Write_rows: table id 114 flags: STMT_END_F
  15. BINLOG '
  16. 69L2WBMxdQAALQAAAEUCAAAAAHIAAAAAAAEABG15ZGIAAmsyAAEDAACea9af
  17. 69L2WB4xdQAAKAAAAG0CAAAAAHIAAAAAAAEAAgAB//5lAAAAiNpRQQ==
  18. '/*!*/;
  19. ### INSERT INTO `mydb`.`k2`
  20. ### SET
  21. ###   @1=101
  22. # at 834
  23. #170419 11:00:59 server id 30001  end_log_pos 652 CRC32 0xf876844e      Xid = 7396
  24. COMMIT/*!*/;

查看从库的binlog:

 
 
 
 
  1. #170419 11:00:59 server id 30001  end_log_pos 463 CRC32 0x6ede3a0d      Anonymous_GTID  last_committed=1        sequence_number=2
  2. SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
  3. # at 463
  4. #170419 11:00:59 server id 30001  end_log_pos 526 CRC32 0x5fac2d32      Query   thread_id=553   exec_time=0     error_code=0
  5. SET TIMESTAMP=1492570859/*!*/;
  6. BEGIN
  7. /*!*/;
  8. # at 526
  9. #170419 11:00:59 server id 30001  end_log_pos 571 CRC32 0xb51f8ec9      Table_map: `mydb`.`k2` mapped to number 108
  10. # at 571
  11. #170419 11:00:59 server id 30001  end_log_pos 611 CRC32 0xfa578a3f      Write_rows: table id 108 flags: STMT_END_F
  12. BINLOG '
  13. 69L2WBMxdQAALQAAADsCAAAAAGwAAAAAAAEABG15ZGIAAmsyAAEDAADJjh+1
  14. 69L2WB4xdQAAKAAAAGMCAAAAAGwAAAAAAAEAAgAB//5lAAAAP4pX+g==
  15. '/*!*/;
  16. ### INSERT INTO `mydb`.`k2`
  17. ### SET
  18. ###   @1=101
  19. # at 611
  20. #170419 11:00:59 server id 30001  end_log_pos 642 CRC32 0xc3a619a0      Xid = 12
  21. COMMIT/*!*/;

(5) 总结

通过分析上述binlog内容,relay log中并没有记录相同的insert语句,但从库的binlog显示已经执行过该语句,当从库重启后,试图再次执行相同的insert语句,从而导致插入语句的主键冲突。

(6) 说明

如果复制使用GTID,那么GTID的特性会使从库不执行相同的语句。

如果在5.7版本使用多线程复制,那么mts_recovery会修复这个问题。

只有在非多线程复制、非GTID复制的情况下才可能出现这个错误。

二、总结

如果复制发生了错误,通过收集上述复制相关信息和错误相关信息,分析这些信息中与正常复制异常的地方,便可为排查复制错误提供更多的信息。

当然,复制的错误是多种多样的,并不是所有的错误都可以排查到具体原因。很多复制错误是较难或者无法进行排查的,比如主库或者从库的binlog日志文件已经丢失、关闭binlog后执行某些操作导致复制不一致,又或者某些内核BUG导致MySQL的复制逻辑本身发生了异常等。

【本文是专栏机构作者“大U的技术课堂”的原创文章,转载请通过微信公众号(ucloud2012)联系作者】

 戳这里,看该作者更多好文

本文标题:操作解析:MySQL如何查看复制信息并排查问题(下)
网址分享:http://www.hantingmc.com/qtweb/news46/15496.html

网站建设、网络推广公司-创新互联,是专注品牌与效果的网站制作,网络营销seo公司;服务项目有等

广告

声明:本网站发布的内容(图片、视频和文字)以用户投稿、用户转载内容为主,如果涉及侵权请尽快告知,我们将会在第一时间删除。文章观点不代表本网站立场,如需处理请联系客服。电话:028-86922220;邮箱:631063699@qq.com。内容未经允许不得转载,或转载时需注明来源: 创新互联