「如何实现流动式软件发布」线上课堂开课啦,快来报名参与课堂抽奖吧~ 了解详情
写点什么

论 MySQL 如何查看复制信息和排查复制问题(下)

2019 年 11 月 12 日

论MySQL如何查看复制信息和排查复制问题(下)

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


查看主库 binlog 日志


查看主库的 binlog 日志文件列表,可能会发现主库的 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
复制代码


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


-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
复制代码


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


03 从库没有执行主库复制的语句(mysql-5.6)

由于 GTID 的特性,SQL 线程不会去执行相同的 GTID 对应的事务,即如果 SQL 线程发现从 relay log 中读取到的事务对应的 GTID 已经存在于从库的 GTID_EXECUTED 中,那么 SQL 线程便不会存在。


1. 错误原因

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


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


2.错误信息

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


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


3.原因分析过程

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


查看 error log


Error log 中记录错误信息:


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
复制代码


查看 show slave status


show slave status 显示的信息全部正常,无从库执行事务的 binlog 产生。这里不排除从库关闭 binlog 执行 drop table 操作的可能。


查看表


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


解析 binlog 日志


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


#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 日志,查找是否存在建表的事务日志:


#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=0use `mydb`/*!*/;SET TIMESTAMP=1492519789/*!*/;insert into mydb.mytbl values (1)/*!*/;……
复制代码


这时我们发现对于相同的 GTID,从库和主机执行的语句是不相同的。通过上述分析,我们推断是从库并没有执行建表语句,从而导致主库数据不一致。


4.说明

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
复制代码


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


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
复制代码


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

1. 错误原因

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


2. 错误信息

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


创建 FEDERATED 引擎的表失败:


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,) ENGINE=FEDERATED DEFAULT CHARSET=utf8 CONNECTION='s'', Error_code: 143
复制代码


3.原因分析过程

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


查看 error log


Error log 中记录错误信息:


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.
复制代码


查看主库和从库的 server 表


主库中 server 表中存在名字为 s 的记录:



从库中不存在名字为 s 的记录:



查看 CREATE SERVER 文档说明


文档中记录,create server 语句并不会记录到 binlog 中。所以导致了主库和从库的数据不一致。复制无法正常进行。


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


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

当变量 relay_log_info_repository 设置为 FILE 时,从库的 SQL 线程每次执行完一个事务后,会把对应的文件和位置信息更新到文件 relay_log.info 中。用于在从库重启时,SQL 能够从正确的位置继续进行复制。


1.错误原因

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


2.错误信息

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


创建库或者表失败:


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
复制代码


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


3.原因分析过程

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


查看 error log


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


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: 6162017-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: 10622017-04-19T03:02:15.459526Z 4 [Warning] Slave: Duplicate entry '101' for key 'PRIMARY' Error_code: 1062
复制代码


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


查看 show slave status


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


查看表 mydb.k2


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


查看从库的 relay log 和 binlog


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


#170419 11:00:22 server id 30001  end_log_pos 403 CRC32 0x0ef99927      Xid = 7395COMMIT/*!*/;# 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                      对应主机的事务执行的时间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=0SET 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 '69L2WBMxdQAALQAAAEUCAAAAAHIAAAAAAAEABG15ZGIAAmsyAAEDAACea9af69L2WB4xdQAAKAAAAG0CAAAAAHIAAAAAAAEAAgAB//5lAAAAiNpRQQ=='/*!*/;### INSERT INTO `mydb`.`k2`### SET### @1=101# at 834#170419 11:00:59 server id 30001 end_log_pos 652 CRC32 0xf876844e Xid = 7396COMMIT/*!*/;
复制代码


查看从库的 binlog:


#170419 11:00:59 server id 30001  end_log_pos 463 CRC32 0x6ede3a0d      Anonymous_GTID  last_committed=1        sequence_number=2SET @@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=0SET 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+169L2WB4xdQAAKAAAAGMCAAAAAGwAAAAAAAEAAgAB//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 = 12COMMIT/*!*/;
复制代码


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


4.说明

如果复制使用 GTID,那么 GTID 的特性会使从库不执行相同的语句;如果复制使用多线程复制,那么 mts_recovery 会修复这个问题;只有在非多线程复制、非 GTID 复制的情况下才可能出现这个错误。


版本和配置

总体来说,版本和配置的不同,只是会造成各种信息的显示格式不同,并不会对上述的方法造成过多的影响。


01 版本

上述信息收集和分析的举例均是在 MySQL-5.7 版本上进行的举例,不同的大版本在信息的内容或者信息的存放方式上可能存在一定的差异。


MySQL-5.6 版本与 MySQL-5.7 版本在复制相关信息上存在以下差异:


1.日志:

在 MySQL-5.6 在停止复制时,error log 会有错误的信息记录:


2017-04-18 17:32:46 682 [Note] Error reading relay log event: slave SQL thread was killed2017-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 event2017-04-18 17:32:46 682 [Note] Slave I/O thread exiting, read up to log 'b5620.000004', position 151
复制代码


2.GTID:

MySQL-5.6 的 gtid_executed 以 global system variables 的方式的展现,MySQL-5.7 是以 mysql.gtid_executed 表的方式展现。


3.BINLOG:

MySQL-5.6 版本在使用自增 ID 时,会使用如下 event 来记录自增 ID。


02 配置

主要体现差异的配置包括 gtid_mode 和 binlog_format。


1.gtid_mode

当 gtid 开启时,gtid 作为判断事务是由谁执行,是否执行过、事务接收和执行进度的判断标准。同时可以通过 show slave status 可以直观的看出 gtid 的接收、执行的情况。


当 gtid 关闭时,file 和 pos 作为接收和执行的判断标准,server_id 作为事务由谁执行的标准。但是事务对应的所有的 server_id 并没有完全的展现出来,所以对于我们排查问题,造成一定的困难。


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=0SET 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 'ceD1WBMxdQAALQAAAHgBAAAAAHIAAAAAAAEABG15ZGIAAm0xAAEDAAHN19rPceD1WB4xdQAAKAAAAKABAAAAAHIAAAAAAAEAAgAB//4NAAAAvuoI7Q=='/*!*/;### INSERT INTO `mydb`.`m1`### SET### @1=13# at 416
复制代码


总结

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


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


本文转载自公众号 UCloud 技术(ID:ucloud_tech)。


原文链接:


https://mp.weixin.qq.com/s/pgbcnY0rsIfoS2MAuKX9lQ


2019 年 11 月 12 日 18:54258

评论

发布
暂无评论
发现更多内容

架构师训练营第 1 期第 9 周作业

好吃不贵

极客大学架构师训练营

Week 9 作業

Christy LAW

MySQL 连接为什么挂死了?

Java架构师迁哥

训练营第九周作业 1

仲夏

极客大学架构师训练营

算法讲解|贪心算法的理解与分析

Java架构师迁哥

并发编程Bug的源头-原子性

996小迁

Java 程序员 架构 面试 并发编程

数字货币交易所开发价格,深圳区块链交易所系统APP开发

13530558032

第八周作业 1

Yangjing

极客大学架构师训练营

第九周作业

fmouse

极客大学架构师训练营

架构师训练营第 1 期 - 第九周作业

Todd-Lee

极客大学架构师训练营

MyBatis 面试题(附答案解析)

比伯

Java 大数据 编程 架构 面试

Redis 分布式锁原理看这篇就够了, 循循渐进

龙台的技术笔记

redis 架构 分布式 分布式锁

接口测试之json中的key获取

测试人生路

接口测试

2021年Java程序员请先把这几项硬技能熟悉掌握,再想着跳槽拿高薪

Java架构之路

Java 编程 程序员 架构 面试

一张图片一份文档,我想redis就到这里吧,剩下的只有实践了

小Q

Java redis 学习 编程 面试

交易所量化机器人搭建--市值管理机器人

13530558032

接口的幂等性的多重考虑,你会了吗?

moon聊技术

Java 接口

奉劝各位准备面试的Java程序员耗子尾汁,赶紧扔掉网上那些千篇一律的面试题

Java架构之路

Java 程序员 架构 面试 编程语言

作业-第5周

arcyao

阿里内部“新鲜出炉”手慢无!首发面试终极指南V3.0,符合一线大厂面试知识点+面试题

Java架构追梦

Java 阿里巴巴 架构 分布式 面试手册

Week 8 作業

Christy LAW

网络冲浪信任危机频发,区块链能否破局?

CECBC区块链专委会

区块链 征信透明

看“区块链”如何为外贸企业融资

CECBC区块链专委会

区块链 银行

Java程序员工作三年,月薪达到38K,只因他掌握了这七大技能树

Crud的程序员

Java 数据库 编程 架构

4年Java开发经验,从传统公司裸辞之后足足准备了3个月,终于拿到美团、京东、字节跳动等大厂offer

Java架构之路

Java 程序员 架构 面试 编程语言

React 灵魂 23 问

局外人

Java 前端 React

Week 8 學習總結

Christy LAW

Week 9 學習總結

Christy LAW

并发编程Bug的源头-原子性

Java架构师迁哥

合约API跟单系统开发方案,智能合约跟单软件

13530558032

区块链钱包开发功能与优势,数字货币钱包APP开发

13530558032

论MySQL如何查看复制信息和排查复制问题(下)-InfoQ