为什么mysqldump --master-data记录的binlog位置不准

Question

mysql版本是5.7.20
1、备份主库

mysqldump -S /tmp/mysql_5000.sock --single-transaction --events --triggers --routines --master-data=2 --set-gtid-purged=off -B db1 db2 db3 db4 > bak_0219.sql

2、恢复数据到从库

mysql -S /tmp/mysql_5001.sock < bak_0219.sql

3、查看binlog位置

head -25 bak_0219.sql

显示如下

#CHANGE MASTER TO MASTER_LOG_FILE='binlog.001404', MASTER_LOG_POS=552304092;

4、创建主从复制：

mysql -S  /tmp/mysql_5001.sock

CHANGE MASTER TO master_host='10.xxxx',master_port=5000,master_user='repl',master_password='xxxxx',MASTER_LOG_FILE='binlog.001404', MASTER_LOG_POS=552304092;

start slave;

show slave status \G
*************************** 1. row ***************************
Slave_IO_State: Waiting for source to send event
Master_Host: 10.xxx
Master_User: repl
Master_Port: 5000
Connect_Retry: 60
Master_Log_File: binlog.001404
Read_Master_Log_Pos: 651038715
Relay_Log_File: relay.000002
Relay_Log_Pos: 2715
Relay_Master_Log_File: binlog.001404
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table: db1.%,db2.%,db3.%,db4.%
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 2 failed executing transaction '1032978c-7f39-11e8-994a-fa8df5b38500:251059134' at source log binlog.001404, end_log_pos 552315580. 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

mysql> select * from performance_schema.replication_applier_status_by_worker;

Worker 2 failed executing transaction '1032978c-7f39-11e8-994a-fa8df5b38500:251059134' at source log binlog.001404, end_log_pos 552315580; Could not execute Write_rows event on table db1.st_ruappsrelationship; Duplicate entry '2402191318160000109' for key 'st_ruappsrelationship.PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's source log binlog.001404, end_log_pos 552315580 | 2024-02-19 17:43:09.052577

我解析了binlog，如下：

这个at 552304092 就是备份文件里面记录的值：

#240219 13:18:13 server id 2507386  end_log_pos 552304092 CRC32 0x6a5c6bf4     Query    thread_id=772910    exec_time=0    error_code=0
SET TIMESTAMP=1708319893/*!*/;
XA COMMIT X'33633135363666652d326261392d346531622d613533392d6166643135666162356632323a31393334363430',X'31393334363430',1
/*!*/;
# at 552304092
#240219 13:18:14 server id 2507386  end_log_pos 552304157 CRC32 0xc6a54d93     GTID    last_committed=598817    sequence_number=598818    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
一些update 其他表的语句 ....
end_log_pos 552315580 这块就是show slave status 看到的mysql主从同步停止的地方；而 @1=2402191318160000109就是数据冲突
值。
#240219 13:18:16 server id 2507386  end_log_pos 552315460 CRC32 0x11810203     Table_map: `qlw_nxin_com`.`st_ruappsrelationship` mapped to number 1150406
# at 552315460
#240219 13:18:16 server id 2507386  end_log_pos 552315580 CRC32 0x355b7e28      Write_rows: table id 1150406 flags: STMT_END_F
### INSERT INTO `db1.`st_ruappsrelationship`
### SET
###   @1=2402191318160000109 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @3=2401221035110000150 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @4=1272945 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @5=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @6=201511260104402866 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1 /* INT meta=0 nullable=0 is_null=0 */
###   @8='1' /* STRING(3) meta=65027 nullable=0 is_null=0 */
###   @9=1708319896 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
###   @10=2145715200 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
###   @11=2046994 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @12=1708319896 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
###   @13=2046994 /* LONGINT meta=0 nullable=1 is_null=0 */
# at 552315580
#240219 13:18:16 server id 2507386  end_log_pos 552315661 CRC32 0x93c09854      Query   thread_id=773590        exec_time=0     error_code=0
SET TIMESTAMP=1708319896/*!*/;
COMMIT

通过查看bak_0219.sql备份，发现表里面的@1=2402191318160000109数据确实已经就存在了，所以binlog里面又执行了一遍insert @1=2402191318160000109导致主键冲突。

不知道为什么，mysqldump --master-data 记录的binlog，比实际位置提前了。

是mysqldump的bug还是我使用方法有问题？

Answer 1

让阿豪来帮你解答，本回答参考chatgpt3.5编写提供，如需一对一服务私聊我哦

问题：根据给出的备份文件和binlog信息，解析出主从同步停止的原因和数据冲突的值。并给出结构鲜明的解析过程。 解析过程：

1. 备份主库：使用mysqldump命令备份主库，指定单事务、事件、触发器、存储过程、关闭GTID自动添加，并输出到bak_0219.sql文件中。
2. 恢复数据到从库：使用mysql命令，从备份文件bak_0219.sql中还原数据到从库。
3. 查看binlog位置：使用head命令查看备份文件的前25行，并找到变更日志位置，得到主从同步时的位置信息。
4. 创建主从复制：使用mysql命令，设置主库连接参数及复制起点，并启动从库复制，查看从库状态确认复制是否成功。
5. 解析binlog：根据show slave status返回的信息，可知主从同步停止了，而造成数据冲突的原因是一个插入语句中发生了主键重复的情况。 因此，主从同步停止的原因是由于数据冲突导致，数据冲突的值是2402191318160000109。 代码如下：

# 备份主库
mysqldump -S /tmp/mysql_5000.sock --single-transaction --events --triggers --routines --master-data=2 --set-gtid-purged=off -B  db1 db2 db3 db4 > bak_0219.sql
# 恢复数据到从库
mysql -S  /tmp/mysql_5001.sock  <  bak_0219.sql
# 查看binlog位置
head -25  bak_0219.sql
# 创建主从复制并查看从库状态
mysql -S  /tmp/mysql_5001.sock
CHANGE MASTER TO master_host='10.xxxx',master_port=5000,master_user='repl',master_password='xxxxx',MASTER_LOG_FILE='binlog.001404', MASTER_LOG_POS=552304092;
start slave;
show slave status \G