GreatSQL 自动开启复制导致同步报错

头像
GreatSQL社区
     福建
    阅读 15 分钟

    GreatSQL 自动开启复制导致同步报错

    1.背景概述

    目前需要将生产数据恢复到一个单实例，再将单实例和生产节点配置主从关系，由于单表数据量较大，时间比较有限，考虑到导入导出的时间，并且GreatSQL支持XtraBackup备份恢复，能够加速数据的恢复，因此决定使用XtraBackup备份工具进行数据的迁移；

    在数据恢复完成后进行数据同步，从库发生报错 1062 主键冲突，通过解析relaylog，根据relaylog中的insert记录，以主键id字段为查询条件进行查询，发现从库中存在该条记录；回到恢复完成时，解析当前binlog发现该条记录写入binlog时间和数据库启动时间相近，且error日志中存在slave等关键字，进一步确认发现复制关系已自动建立，导致关闭期间主库新增数据依然正常同步到从库，从而导致从库报错.

    2.问题复现

    本次测试基于 GreatSQL 8.0.32

    2.1 初始化3个单机实例

    初始化过程略，其中前两个实例为主从关系，第三个实例是备份恢复完成后原从库的从库

    2.2 主节点创建测试表

    greatsql> CREATE DATABASE test;
greatsql> USE test;

greatsql> CREATE TABLE t1 (id INT,name VARCHAR(30),age INT,insert_time DATE not null,unique key (id)) ENGINE=INNODB;

greatsql> INSERT INTO t1 values
(1,'小红',10,'2015-09-28'),
(2,'小绿',11,'2016-09-29'),
(3,'小黄',12,'2024-07-09'),
(4,'小蓝',13,'2024-08-06'),
(5,'小黑',14,'2024-08-07');

    2.3 从节点查询数据

    greatsql> SELECT * FROM test.t1;
+------+--------+------+-------------+
| id   | name   | age  | insert_time |
+------+--------+------+-------------+
|    1 | 小红   |   10 | 2015-09-28  |
|    2 | 小绿   |   11 | 2016-09-29  |
|    3 | 小黄   |   12 | 2024-07-09  |
|    4 | 小蓝   |   13 | 2024-08-06  |
|    5 | 小黑   |   14 | 2024-08-07  |
+------+--------+------+-------------+
5 rows in set (0.01 sec)

    2.4 执行全量备份

    在从节点执行备份任务
    $ /data/tool/percona-xtrabackup-8.0.32-26-34cf2908-linux-x86_64-glibc2.17/bin/xtrabackup --defaults-file=/data/my5506.cnf --user=root --password='!QAZ2wsx' --host=172.17.134.93 --port=5506 --backup --compress --target-dir=/data/backup/`date +%Y%m%d`/

    2.5 备份恢复

    在第三个实例上利用备份文件恢复数据
    ##解压备份文件
$ /data/tool/percona-xtrabackup-8.0.32-26-34cf2908-linux-x86_64-glibc2.17/bin/xtrabackup --decompress --remove-original --target-dir=/data/backup/20240813

##准备数据
$ /data/tool/percona-xtrabackup-8.0.32-26-34cf2908-linux-x86_64-glibc2.17/bin/xtrabackup --prepare --target-dir=/data/backup/20240813

##拷贝数据（需要将源目录进行备份，且恢复目录要为空）
$ /data/tool/percona-xtrabackup-8.0.32-26-34cf2908-linux-x86_64-glibc2.17/bin/xtrabackup --datadir=/data/GreatSQL --copy-back --target-dir=/data/backup/20240813

##启动数据库实例
$ /data/app/GreatSQL-8.0.32-25-Linux-glibc2.17-x86_64/bin/mysqld_safe --defaults-file=/data/my5506.cnf --user=greatdb &

    继续在主节点插入新数据

    greatsql> INSERT INTO t1 values (6,'小紫',21,'2024-08-12');

    从节点查询数据

    greatsql> SELECT * FROM t1;
+------+--------+------+-------------+
| id   | name   | age  | insert_time |
+------+--------+------+-------------+
|    1 | 小红   |   10 | 2015-09-28  |
|    2 | 小绿   |   11 | 2016-09-29  |
|    3 | 小黄   |   12 | 2024-07-09  |
|    4 | 小蓝   |   13 | 2024-08-06  |
|    5 | 小黑   |   14 | 2024-08-07  |
|    6 | 小紫   |   21 | 2024-08-12  |
+------+--------+------+-------------+
6 rows in set (0.01 sec)

    注意：这里的从节点是指原主从环境的从节点，而不是利用备份文件恢复后配置的从节点。原主从环境是正常同步的，不做其他的操作。

    2.6 新实例建立复制关系

    新实例恢复完成后，根据备份文件gtid信息，配置和原从节点的同步
    greatsql> RESET MASTER;
Query OK, 0 rows affected (0.04 sec)

greatsql> RESET SLAVE ALL;
Query OK, 0 rows affected, 1 warning (0.03 sec)

greatsql> SET GLOBAL GTID_PURGED='28093c86-5631-11ef-87f4-00163eab83df:1-3';
Query OK, 0 rows affected (0.00 sec)

greatsql> SHOW MASTER STATUS;
+---------------+----------+--------------+------------------+------------------------------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+---------------+----------+--------------+------------------+------------------------------------------+
| binlog.000001 |      157 |              |                  | 28093c86-5631-11ef-87f4-00163eab83df:1-3 |
+---------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

greatsql> CHANGE MASTER to MASTER_HOST = '172.17.134.93',MASTER_USER = 'replabd',MASTER_PASSWORD = 'greatdb',MASTER_PORT = 5506,MASTER_LOG_FILE ='binlog.000002', MASTER_LOG_POS = 197 for CHANNEL 'slave_5506';
Query OK, 0 rows affected, 7 warnings (0.02 sec)

greatsql> START SLAVE FOR CHANNEL 'slave_5506';
Query OK, 0 rows affected, 1 warning (0.04 sec)

    2.7 查看复制状态

    greatsql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 172.17.134.93
                  Master_User: replabd
                  Master_Port: 5506
                Connect_Retry: 60
              Master_Log_File: binlog.000002
          Read_Master_Log_Pos: 963
               Relay_Log_File: gip-relay-bin-slave_5506.000002
                Relay_Log_Pos: 323
        Relay_Master_Log_File: binlog.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1062
                   Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '28093c86-5631-11ef-87f4-00163eab83df:4' at master log binlog.000002, end_log_pos 549. 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
          Exec_Master_Log_Pos: 197
              Relay_Log_Space: 1308
...

greatsql> SELECT * FROM performance_schema.replication_applier_status_by_worker limit 1\G
*************************** 1. row ***************************
                                           CHANNEL_NAME: slave_5506
                                              WORKER_ID: 1
                                              THREAD_ID: NULL
                                          SERVICE_STATE: OFF
                                      LAST_ERROR_NUMBER: 1062
                                     LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '28093c86-5631-11ef-87f4-00163eab83df:4' at master log binlog.000002, end_log_pos 549; Could not execute Write_rows event on table test.t1; Duplicate entry '6' for key 't1.PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 549
 ......

    从 performance_schema.replication_applier_status_by_worker 表详细错误信息可以看到，从库在test.t1表，主键值为6上报1062主键冲突错误

    2.8 解析从库relay log

    SET @@SESSION.GTID_NEXT= '28093c86-5631-11ef-87f4-00163eab83df:4'/*!*/;
# at 409
#240814 14:14:35 server id 135506  end_log_pos 353 CRC32 0x8fe3125e     Query   thread_id=9     exec_time=0     error_code=0
SET TIMESTAMP=1723616075/*!*/;
SET @@session.pseudo_thread_id=9/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168637984/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 479
#240814 14:14:35 server id 135506  end_log_pos 428 CRC32 0x0ac8f16a     Rows_query
# insert into t1 values
#  (6,'小紫',21,'2024-08-12')
# at 554
#240814 14:14:35 server id 135506  end_log_pos 487 CRC32 0x46a55e3a     Table_map: `test`.`t1` mapped to number 89
# has_generated_invisible_primary_key=1
# at 613
#240814 14:14:35 server id 135506  end_log_pos 549 CRC32 0x82672058     Write_rows: table id 89 flags: STMT_END_F
### INSERT INTO `test`.`t1`
### SET
###   @1=6 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=6 /* INT meta=0 nullable=1 is_null=0 */
###   @3='小紫' /* VARSTRING(120) meta=120 nullable=1 is_null=0 */
###   @4=21 /* INT meta=0 nullable=1 is_null=0 */
###   @5='2024:08:12' /* DATE meta=0 nullable=0 is_null=0 */
# at 675
#240814 14:14:35 server id 135506  end_log_pos 580 CRC32 0xbf6d9a69     Xid = 11
COMMIT/*!*/;
# at 706
#240814 14:14:36 server id 135506  end_log_pos 666 CRC32 0x7a9e84ef     GTID    last_committed=1        sequence_number=2       rbr_only=yes    original_committed_timestamp=1723616076007388   immediate_commit_timestamp=1723616076225999     transaction_length=383
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

    可以看到，insert 插入的具体记录

    2.9 根据relay log中的内容去从库查询数据

    greatsql> SELECT * FROM test.t1 where id = 6;
+------+--------+------+-------------+
| id   | name   | age  | insert_time |
+------+--------+------+-------------+
|    6 | 小紫   |   21 | 2024-08-12  |
+------+--------+------+-------------+
1 row in set (0.00 sec)

    从库确实存在这条记录，那为什么数据会重复呢？

    2.10 回到备份恢复完成时

    查看新实例当前gtid

    greatsql> SHOW MASTER STATUS \G
*************************** 1. row ***************************
             File: binlog.000005
         Position: 963
     Binlog_Do_DB: 
 Binlog_Ignore_DB: 
Executed_Gtid_Set: 28093c86-5631-11ef-87f4-00163eab83df:1-5
1 row in set (0.00 sec)

    查询数据

    greatsql> SELECT * FROM test.t1 where id = 6;
+------+--------+------+-------------+
| id   | name   | age  | insert_time |
+------+--------+------+-------------+
|    6 | 小紫   |   21 | 2024-08-12  |
+------+--------+------+-------------+
1 row in set (0.00 sec)

    可以看到，当利用备份文件恢复完成后，查询该数据是存在的，且当前gtid信息和备份文件 xtrabackup_info 记录的gtid信息不一致，明显gtid值较大

    2.11 解析当前 binlog

    # at 126
#240814 15:11:53 server id 2295506  end_log_pos 197 CRC32 0xd635e779    Previous-GTIDs
# 28093c86-5631-11ef-87f4-00163eab83df:1-3
# at 197
#240814 14:14:35 server id 135506  end_log_pos 283 CRC32 0x29a5e5d0     GTID    last_committed=0        sequence_number=1       rbr_only=yes    original_committed_timestamp=1723616075269734   immediate_commit_timestamp=1723619515286089     transaction_length=383
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1723616075269734 (2024-08-14 14:14:35.269734 CST)
# immediate_commit_timestamp=1723619515286089 (2024-08-14 15:11:55.286089 CST)
/*!80001 SET @@session.original_commit_timestamp=1723616075269734*//*!*/;
/*!80014 SET @@session.original_server_version=80032*//*!*/;
/*!80014 SET @@session.immediate_server_version=80032*//*!*/;
SET @@SESSION.GTID_NEXT= '28093c86-5631-11ef-87f4-00163eab83df:4'/*!*/;
# at 283
#240814 14:14:35 server id 135506  end_log_pos 353 CRC32 0x7fd5bbc9     Query   thread_id=7     exec_time=3440  error_code=0
SET TIMESTAMP=1723616075/*!*/;
SET @@session.pseudo_thread_id=7/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168637984/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 353
#240814 14:14:35 server id 135506  end_log_pos 428 CRC32 0x0ac8f16a     Rows_query
# insert into t1 values
#  (6,'小紫',21,'2024-08-12')
# at 428
#240814 14:14:35 server id 135506  end_log_pos 487 CRC32 0x6ab5cc7d     Table_map: `test`.`t1` mapped to number 86
# has_generated_invisible_primary_key=1
# at 487
#240814 14:14:35 server id 135506  end_log_pos 549 CRC32 0xa97243cd     Write_rows: table id 86 flags: STMT_END_F
### INSERT INTO `test`.`t1`
### SET
###   @1=6 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=6 /* INT meta=0 nullable=1 is_null=0 */
###   @3='小紫' /* VARSTRING(120) meta=120 nullable=1 is_null=0 */
###   @4=21 /* INT meta=0 nullable=1 is_null=0 */
###   @5='2024:08:12' /* DATE meta=0 nullable=0 is_null=0 */
# at 549
#240814 14:14:35 server id 135506  end_log_pos 580 CRC32 0x6c8881dc     Xid = 3
COMMIT/*!*/;

    可以看到id为6的记录写入binlog文件的时间和数据库实例启动时间基本一致，说明数据是在启动过程中写入的，且error.log中出现了关键字Slave I/O thread & Slave SQL thread不得不怀疑是否已经建立了复制关系？

    file

    2.12 新实例查询是否存在复制关系

    greatsql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 172.17.140.13
                  Master_User: replabc
                  Master_Port: 5506
                Connect_Retry: 60
              Master_Log_File: binlog.000002
          Read_Master_Log_Pos: 959
               Relay_Log_File: gip-relay-bin-master_5506.000002
                Relay_Log_Pos: 1129
        Relay_Master_Log_File: binlog.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
...

    可以看到新实例恢复完成后，复制关系已经建立，且同步正常，为什么会出现这种情况？

    2.13 查看复制元数据信息和启动参数

    greatsql> SELECT * FROM slave_master_info \G
*************************** 1. row ***************************
                Number_of_lines: 33
                Master_log_name: binlog.000002
                 Master_log_pos: 197
                           Host: 172.17.140.13
                      User_name: replabc
                  User_password: !QAZ2wsx
                           Port: 5506
                  Connect_retry: 60
                    Enabled_ssl: 0
                         Ssl_ca: 
                     Ssl_capath: 
                       Ssl_cert: 
                     Ssl_cipher: 
                        Ssl_key: 
         Ssl_verify_server_cert: 0
                      Heartbeat: 30
                           Bind: 
             Ignored_server_ids: 0
                           Uuid: 28093c86-5631-11ef-87f4-00163eab83df
                    Retry_count: 86400
                        Ssl_crl: 
                    Ssl_crlpath: 
          Enabled_auto_position: 1
                   Channel_name: master_5506
                    Tls_version: 
                Public_key_path: 
                 Get_public_key: 0
              Network_namespace: 
   Master_compression_algorithm: uncompressed
  Master_zstd_compression_level: 3
               Tls_ciphersuites: NULL
Source_connection_auto_failover: 0
                      Gtid_only: 0
1 row in set (0.00 sec)

greatsql> SELECT * FROM slave_relay_log_info \G
*************************** 1. row ***************************
                             Number_of_lines: 14
                              Relay_log_name: ./gip-relay-bin-master_5506.000002
                               Relay_log_pos: 1129
                             Master_log_name: binlog.000002
                              Master_log_pos: 959
                                   Sql_delay: 0
                           Number_of_workers: 64
                                          Id: 1
                                Channel_name: master_5506
                   Privilege_checks_username: NULL
                   Privilege_checks_hostname: NULL
                          Require_row_format: 0
             Require_table_primary_key_check: STREAM
 Assign_gtids_to_anonymous_transactions_type: OFF
Assign_gtids_to_anonymous_transactions_value: 
1 row in set (0.01 sec)

greatsql> SHOW VARIABLES LIKE '%skip%start%';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| skip_replica_start | OFF   |
| skip_slave_start   | OFF   |
+--------------------+-------+
2 rows in set (0.00 sec)

    MySQL 手册介绍

    file

    副本服务器会创建多个信息存储库以用于复制过程，其中包括：

    • 副本连接元数据存储库，包含复制接收器线程连接到复制源服务器并从源的二进制日志检索事务所需的信息。连接元数据存储库被写入mysql.slave_master_info 表中。
    • 副本的应用程序元数据存储库，包含复制应用程序线程需要从副本的中继日志读取和应用事务的信息。应用程序元数据存储库被写入 mysql.slave_relay_log_info表中。

    file

    • 从MySQL 8.0.26 开始使用--skip-replica-start代替，之前的版本可以使用 --skip-slave-start，默认值为OFF。
    • 告诉副本服务器在服务器启动时不要启动复制 I/O（接收器）和 SQL（应用程序）线程。若要稍后启动线程，请使用 START REPLICA 语句。

    官方文档的这两段描述可以解释为什么在数据库服务启动之后，同步关系会自动建立，若主库状态正常，且binlog文件保存完整，则I/O和SQL线程状态都为YES。

    2.14 解决方法

    1. 新实例恢复完成后，启动前在配置文件中添加参数skip_replica_start=1或启动时加上--skip-replica-start=1
    2. 配置同步，再次查看同步正常
    greatsql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: 172.17.134.93
                  Master_User: replabd
                  Master_Port: 5506
                Connect_Retry: 60
              Master_Log_File: binlog.000004
          Read_Master_Log_Pos: 197
               Relay_Log_File: gip-relay-bin-slave_5506.000009
                Relay_Log_Pos: 363
        Relay_Master_Log_File: binlog.000004
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
...
1 row in set, 1 warning (0.00 sec)

    3.总结

    1. 在进行维护或修改从库配置时，可能需要从库停止复制。这时设置skip-replica-starts可以确保从库在重启时不会自动启动复制进程，从而避免在未完成配置调整前意外启动复制。
    2. 当需要在从库上进行数据恢复或其他涉及数据修改的操作时，停止复制是必要的。设置skip-replica-starts=1可以确保在操作完成并手动启动复制前，复制进程不会自动启动。

    Enjoy GreatSQL :)

    ## 关于 GreatSQL

    GreatSQL是适用于金融级应用的国内自主开源数据库，具备高性能、高可靠、高易用性、高安全等多个核心特性，可以作为MySQL或Percona Server的可选替换，用于线上生产环境，且完全免费并兼容MySQL或Percona Server。

    相关链接： GreatSQL社区 Gitee GitHub Bilibili

    GreatSQL社区：

    社区博客有奖征稿详情：https://greatsql.cn/thread-100-1-1.html

    image-20230105161905827

    技术交流群：

    微信：扫码添加GreatSQL社区助手微信好友，发送验证信息加群。

    image-20221030163217640

    数据库mysql
    GreatSQL社区
    8 声望6 粉丝

    GreatSQL是由万里数据库维护的MySQL分支，专注于提升MGR可靠性及性能，支持InnoDB并行查询特性，是适用于金融级应用的MySQL分支版本。

    « 上一篇
    【GreatSQL优化器-04】贪婪搜索算法浅析
    下一篇 »
    GreatSQL内存消耗异常排查攻略：从系统到应用层面的深入分析

    引用和评论

    推荐阅读
    头像
    GreatSQL内存消耗异常排查攻略：从系统到应用层面的深入分析

    GreatSQL社区

    头像
    在Java程序中监听mysql的binlog

    huan1993赞 11阅读 2.2k

    头像
    Mysql数据库sql优化案例

    杜若赞 5阅读 2.3k

    头像
    数据集汇总｜18个电影/音乐数据集汇总，覆盖影片/歌曲推荐、电影评价、歌词识别、音乐流派······

    超神经HyperAI赞 3阅读 1.4k

    头像
    使用 MongoDB 构建 AI：Gradient Accelerator Block 如何在几秒钟内让您从零开发 AI

    MongoDB数据平台赞 1阅读 12.9k

    头像
    MongoDB Atlas与YoMio.AI近乎完美适配:推理更快速、查询更灵活、场景更丰富

    MongoDB数据平台赞 1阅读 12.4k

    头像
    MongoDB 8.0已全面可用

    MongoDB数据平台阅读 12.1k

    0 条评论
    得票最新