DM同步主键冲突原因及排查恢复

IT那活儿 2022-03-13

2572

点击上方“IT那活儿”，关注后了解更多内容，不管IT什么活儿，干就完了！！！

报错现象

主键冲突：

报错分析

情况1：上游数据存在冲突的情况，例如上游两套Mysql库，分别都有store_bj表，通过DM将上游两张表的数据汇总到下游一张表中，在同步的过程中上游两张表都有id=12的主键的数据，上游mysql中均插入成功，但在同步Tidb进行中出现主键冲突。

-- 解决方法：从上游数据入手，避免重复主键数据，出现主键冲突的报错之后，同步Task任务将被终止，通过重启Task任务可以恢复同步状态。

在任务终止期间，如果上游Mysql继续有相同主键数据更新的操作会在重启Task任务后再次出现主键冲突报错，需要再次进行Task任务的重启。

建议对于报错的主键冲突情况，需要业务开发人员对报错的表操作以及数据进行排查，会存在主键冲突的数据未同步成功的情况。

-- 测试报错及恢复案例：

1）store_bj表结构：

create table store_bj (id int primary key,name varchar(20));
mysql1：
mysql> insert into store_bj values (12,'store_bj_11');Query OK, 1 row affected (0.01 sec)mysql2：
mysql> insert into store_bj values (12,'store_bj_12');Query OK, 1 row affected (0.01 sec)

2）在上游两套Mysql中，均正常插入id=12的数据，但在Tidb中只有成功插入其中一条数据插入，查询Task状态报错：

[tidb@tidb1 ~]$ tiup dmctl --master-addr ***.**.***.134:8261 query-status two_tidb_slave………"subTaskStatus": [{"name": "two_tidb_slave","stage": "Paused","unit": "Sync","result": {"isCanceled": false,"errors": [{"ErrCode": 100*6,"ErrClass": "database","ErrScope": "not-set","ErrLevel": "high","Message": "startLocation: [position: (, 0), gtid-set: ], endLocation: [position: (mysql-bin.000002, 12368), gtid-set: ]: execute statement failed: commit",                               "RawCause": "Error 1062: Duplicate entry '12' for key 'PRIMARY'","Workaround": ""}],"detail": null…………

3）排查DM日志,可以找到对应的主键冲突的报错以及对应表的操作：

[tidb@tidb1 ~]$ cat home/tidb/dm/deploy/dm-worker-8262/log/dm-worker.log………[2021/12/03 16:54:39.773 +08:00] [INFO] [syncer.go:1902] ["meet heartbeat event and then flush jobs"] [task=two_tidb_slave] [unit="binlog replication"][2021/12/03 16:54:39.773 +08:00] [INFO] [syncer.go:3016] ["flush all jobs"] [task=two_tidb_slave] [unit="binlog replication"] ["global checkpoint"="position: (mysql-bin.000002, 12123), gtid-set: (flushed position: (mysql-bin.000002, 12123), gtid-set: )"][2021/12/03 16:54:39.773 +08:00] [INFO] [syncer.go:1119] ["flushed checkpoint"] [task=two_tidb_slave] [unit="binlog replication"] [checkpoint="position: (mysql-bin.000002, 12123), gtid-set: (flushed position: (mysql-bin.000002, 12123), gtid-set: )"][2021/12/03 16:54:39.773 +08:00] [INFO] [syncer.go:1127] ["after last flushing checkpoint, DM has ignored row changes by expression filter"] [task=two_tidb_slave] [unit="binlog replication"] ["number of filtered insert"=0] ["number of filtered update"=0] ["number of filtered delete"=0][2021/12/03 16:54:41.794 +08:00] [ERROR] [db.go:201] ["execute statements failed after retry"] [task=two_tidb_slave] [unit="binlog replication"] [queries="[INSERT INTO `store`.`store_bj` (`id`,`name`) VALUES (?,?)]"] [arguments="[[12 store_bj_12]]"] [error="[code=10006:class=database:scope=not-set:level=high], Message: execute statement failed: commit, RawCause: Error 1062: Duplicate entry '12' for key 'PRIMARY'"][2021/12/03 16:54:41.794 +08:00] [INFO] [syncer.go:2854] ["print status routine exits"] [task=two_tidb_slave] [unit="binlog replication"] [error="context canceled"][2021/12/03 16:54:41.794 +08:00] [INFO] [syncer.go:1696] ["binlog replication main routine quit(context canceled)!"] [task=two_tidb_slave] [unit="binlog replication"] ["last location"="position: (mysql-bin.000002, 12399), gtid-set: "][2021/12/03 16:54:41.828 +08:00] [INFO] [syncer.go:1602] ["flush checkpoints when exit task"] [task=two_tidb_slave] [unit="binlog replication"][2021/12/03 16:54:41.837 +08:00] [INFO] [checkpoint.go:694] ["rollback checkpoint"] [task=two_tidb_slave] [unit="binlog replication"] [component="remote checkpoint"] [schema=store] [table=store_shenzhen] [from="position: (mysql-bin.000002, 10712), gtid-set: "] [to="position: (mysql-bin.000002, 10712), gtid-set: "][2021/12/03 16:54:41.837 +08:00] [WARN] [checkpoint.go:697] ["failed to drop table from schema tracker"] [task=two_tidb_slave] [unit="binlog replication"] [component="remote checkpoint"] [schema=store] [table=store_shenzhen] [error="[schema:1146]Table 'store.store_shenzhen' doesn't exist"][2021/12/03 16:54:41.844 +08:00] [WARN] [syncer.go:681] ["something wrong with rollback global checkpoint"] [task=two_tidb_slave] [unit="binlog replication"] ["previous position"="position: (mysql-bin.000002, 12399), gtid-set: "] ["current position"="position: (mysql-bin.000002, 12123), gtid-set: "][2021/12/03 16:54:41.844 +08:00] [INFO] [subtask.go:292] ["unit process returned"] [subtask=two_tidb_slave] [unit=Sync] [stage=Paused] [status="{\"totalEvents\":1,\"syncerBinlog\":\"(mysql-bin.000002, 12123)\",\"binlogType\":\"remote\"}"][2021/12/03 16:54:41.844 +08:00] [ERROR] [subtask.go:311] ["unit process error"] [subtask=two_tidb_slave] [unit=Sync] ["error information"="{\"ErrCode\":10006,\"ErrClass\":\"database\",\"ErrScope\":\"not-set\",\"ErrLevel\":\"high\",\"Message\":\"startLocation: [position: (, 0), gtid-set: ], endLocation: [position: (mysql-bin.000002, 12368), gtid-set: ]: execute statement failed: commit\",\"RawCause\":\"Error 1062: Duplicate entry '12' for key 'PRIMARY'\"}"][2021/12/03 16:54:45.961 +08:00] [WARN] [task_checker.go:390] ["task can't auto resume"] [component="task checker"] [task=two_tidb_slave]…………

对于报错的同步，建议业务开发人员对DM失败的操作进行排查，对同步的表上游源端和下游成功插入的数据是否有效，未同步成功的数据是否需要进行主键的调整，均需要进行排查。当调整完成后，再次重启Task任务，并检查同步状态。

4）再次重启task任务：

[tidb@tidb1 ~]$ tiup dmctl -master-addr ***.**.***.134:8261 stop-task task3637.yaml[tidb@tidb1 ~]$ tiup dmctl -master-addr ***.**.***.134:8261 start-task task3637.yaml

5）检查同步状态：

[tidb@tidb1 ~]$ tiup dmctl --master-addr ***.**.***.134:8261 query-status two_tidb_slave

情况2：

全量导入数据之前，该主键数据已经存在于下游数据库中。

判断依据：主键写入数据库的时间即（MVCC时间）早于 load 的时间（min(create_time)），查询时间点可以参考情况3。

解决方法：如仅出现一次主键冲突的情况，可以将下游主键数据删掉，恢复同步任务即可；如多次出现主键冲突，建议删除下游数据以及为位点信息后，重新进行全量数据的导入。

情况3：

由于位点信息被清理导致 sql 文件被重复导入(未重现，需要根据情况进行判断，BUG情况需要提交AskTUG专家进行分析)。

判断依据：根据以下信息可了解到在全量迁移阶段开始后，因某种原因导致 sql 文件位点被删除，sql 文件被重复导入，导致主键冲突。

同步任务全量迁移阶段开始时间为：2020-03-17 11:57:36

该数据插入数据库的时间为：2020-03-17 11:57:37

该文件 test.sbtest5.000000005.sql 记录的创建时间以及更新时间都是 2020-03-17 12:20:29

从 dm-worker.log 中 grep test.sbtest5.000000005.sql 发现同步任务开始后，有两次导入该文件。

解决方法：建议清空下游数据，重新导入。

根据冲突主键的 MVCC 版本以及 dm_meta 中的位点信息具体分析：

1）利用 tidb API 查看主键冲突的行的 mvcc 版本，以此来确认该行数据插入数据库的时间

注意：该操作需要保留现场，该操作是从下游 TiDB 中查询。

#主键为 int 类型，handle 即 int 类型主键。

curl http://{TiDBIP}:1**80/mvcc/key/{db}/{table}/{handle}

#主键为非整数类型。

select _tidb_rowid from xxx where trade_no=‘190606LI8OODRTZA5XX1’;curl http://{TiDBIP}:1**80/mvcc/key/{db}/{table}/{_tidb_rowid}

根据上述命令得到如下结果：

下一步操作为根据 pd-ctl 将 commit_ts 转化为对应的时间，即解析 tso。

注：也可以在 TiDB 中调用 select TIDB_PARSE_TSO(415345529804292097); 获取对应时间。

2）在 dm_meta 查询 min(create_time) 来获得 load 第一个文件时的时间，可以认为是全量迁移阶段的开始时间。

3）在 dm_meta 中查看 xxx_loadder_checkpoint 表查看该文件 test.sbtest5.000000005.sql 的详细信息!

4）从 dm-worker 中 grep 查看该主键所在的 .sql 文件出现的时间以及次数

冲突的主键（1292790）所在的文件为 test.sbtest5.000000005.sql

grep test.sbtest5.000000005.sql dm-worker.log

本文作者：陈聪

本文来源：IT那活儿（上海新炬王翦团队）

数据库

文章转载自IT那活儿，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。