Loader 导入时主键冲突

🪐 TiDB 技术问题 备份&数据迁移
1

为提高效率，提问时请尽量提供详细背景信息，问题描述清晰可优先响应。以下信息点请尽量提供：

  • 系统版本 & kernel 版本：
  • TiDB 版本：v3.0.3
  • 磁盘型号：
  • 集群节点分布：1TIDB，1PD，3TIKV
  • 数据量 & region 数量 & 副本数：
  • 集群 QPS、.999-Duration、读写比例：
  • 问题描述（我做了什么）：
    按照TIDB官方ansible部署，因为测试环境跳过了系统检测，所有参数都是默认配置
    然后从开发环境导出数据
    导出语句
    ./bin/mydumper -h 172.18.8.30 -P 3400 -u xxx -p ‘xxx’ -t 16 -F 64 -B xxx --skip-tz-utc -o /DATA1/xxx
    然后使用loader导入
    /DATA1/tools/tidb-tools/tidb-enterprise-tools-latest-linux-amd64/bin/loader -d /DATA1/xxx/ -h 127.0.0.1 -u root -P 4000
    问题：
    再倒入部分数据后，报错
    2019/09/23 18:04:31 loader.go:124: [fatal] Error 1062: Duplicate entry ‘18855454’ for key ‘PRIMARY’
    image
    image2296×148 168 KB

    重试
    删除tidb-loader库和已经导入数据的库后还是会有相同问题
    有时候重试还会有2019/09/23 16:39:39 loader.go:190: [error] init sale_vip.t_collect_honey.000000010.sql checkpoint error:initialize checkpoint: invalid connection这种报错

查看表的批量sql文件，确认只有这一个主键值并且在数据库中已经插入
求大佬解答

2

麻烦完整的 loader 日志打包也传一个，多谢。

3

2019/09/23 18:04:14 db.go:76: [warning] exec sql retry 4 - [USE sale_vip; INSERT INTO qa_log_honey VALUES(41705279,69665354,’’,’’,0,98,1,‘2017-07-22 13:57:43’,0,‘22610828’, UPDATE tidb_loader.checkpoint SET offset=4999885 WHERE id =‘bcc433’ AND filename=‘sale_vip] 2019/09/23 18:04:14 db.go:111: [error] exec sqls[[USE sale_vip; INSERT INTO qa_log_honey VALUES(2631778,58063636,’’,’’,0,37,3,‘2015-08-22 08:51:36’,0,‘0’,2,3,’{" UPDATE tidb_loader.checkpoint SET offset=16999459 WHERE id =‘bcc433’ AND filename=‘sale_vi]] begin failed dial tcp 127.0.0.1:4000: connect: connection refused 2019/09/23 18:04:14 db.go:76: [warning] exec sql retry 4 - [USE sale_vip; INSERT INTO qa_log_honey VALUES(2631778,58063636,’’,’’,0,37,3,‘2015-08-22 08:51:36’,0,‘0’,2,3,’{" UPDATE tidb_loader.checkpoint SET offset=16999459 WHERE id =‘bcc433’ AND filename=‘sale_vi] 2019/09/23 18:04:14 db.go:111: [error] exec sqls[[USE sale_vip; INSERT INTO t_collect_honey VALUES(18158965,36994652,91703574,’’,’’,’’,1,‘2019-07-31 08:37:08’,0,’ UPDATE tidb_loader.checkpoint SET offset=17998918 WHERE id =‘bcc433’ AND filename=‘sale_vi]] begin failed dial tcp 127.0.0.1:4000: connect: connection refused 2019/09/23 18:04:14 db.go:76: [warning] exec sql retry 4 - [USE sale_vip; INSERT INTO t_collect_honey VALUES(18158965,36994652,91703574,’’,’’,’’,1,‘2019-07-31 08:37:08’,0,’ UPDATE tidb_loader.checkpoint SET offset=17998918 WHERE id =‘bcc433’ AND filename='sale_vi] 2019/09/23 18:04:17 status.go:32: [info] [loader] finished_bytes = 953233802, total_bytes = GetAllRestoringFiles4261909137, progress = 22.37 % 2019/09/23 18:04:22 status.go:32: [info] [loader] finished_bytes = 953233802, total_bytes = GetAllRestoringFiles4261909137, progress = 22.37 % 2019/09/23 18:04:27 db.go:137: [warning] update checkpoint affected rows 0 2019/09/23 18:04:27 status.go:32: [info] [loader] finished_bytes = 953233802, total_bytes = GetAllRestoringFiles4261909137, progress = 22.37 % 2019/09/23 18:04:27 db.go:137: [warning] update checkpoint affected rows 0 2019/09/23 18:04:30 db.go:105: [warning] transaction execution costs 8.169627 seconds 2019/09/23 18:04:30 db.go:105: [warning] transaction execution costs 8.339114 seconds 2019/09/23 18:04:30 db.go:105: [warning] transaction execution costs 8.339362 seconds 2019/09/23 18:04:31 db.go:105: [warning] transaction execution costs 8.917922 seconds 2019/09/23 18:04:31 loader.go:124: [fatal] Error 1062: Duplicate entry ‘18855454’ for key ‘PRIMARY’ /home/jenkins/workspace/build_tidb_enterprise_tools_master/go/src/github.com/pingcap/tidb-enterprise-tools/loader/db.go:144: /home/jenkins/workspace/build_tidb_enterprise_tools_master/go/src/github.com/pingcap/tidb-enterprise-tools/loader/db.go:84: /home/jenkins/workspace/build_tidb_enterprise_tools_master/go/src/github.com/pingcap/tidb-enterprise-tools/loader/loader.go:124: file sale_vip.qa_log_honey.000000017.sql

这是报错前的部分日志，完整日志我需要重新跑一遍，磁盘不行，现在只是测试功能

4

2019/09/23 18:04:14 db.go:111: [error] exec sqls[[USE sale_vip; INSERT INTO qa_log_honey VALUES(2631778,58063636,’’,’’,0,37,3,‘2015-08-22 08:51:36’,0,‘0’,2,3,’{" UPDATE tidb_loader.checkpoint SET offset=16999459 WHERE id =‘bcc433’ AND filename=‘sale_vi]] begin failed dial tcp 127.0.0.1:4000: connect: connection refused

通过日志看到在导入过程中出现连接被拒绝的现象。先排查一下网络以及目标集群是否稳定。另外，把Loader 完整日志贴一下

5

loader.log.tar.gz (9.7 KB)
这是全部的loader日志，即使网络或者机器性能瓶颈应该都不会出现主键冲突才对吧，不是会将断点写入tidb_loader库吗

6

loader.log.tar.gz (9.7 KB)
这是完整的日志，但是无论网络或者目标集群是否稳定，不应该主键冲突吧，不是会将断点写入tidb_loader库吗

7

查看日志里面 发现大量的 begin failed dial tcp 127.0.0.1:4000: connect: connection refused 报错，另外 Duplicate entry ‘17629583’ for key ‘PRIMARY’ 麻烦在上下游查下这个 key 对应的数据情况。

8

上下游是指哪里，在mysql里面数据正常，每次报错都是不同的主键值

9

这个是主键信息，上游如果数据重复在mysql里面也会报冲突，并且查看了备份文件没有重复数据，就是不知道为什么做了重复导入

10

目前 loader 导入过程中如果出现网络问题或者下游服务繁忙，因为重试策略，可能会出现数据重复导入的问题。有两点建议：

  1. 检查网络状况和下游负载，适当减少导入并发度尝试重新导入
  2. 使用 DM 进行数据全量导入（DM 已经对这类问题进行了修复）
11

重试策略不基于tidb_loader这个库里面的那个点吗，为什么会重试失败呢

12

loader 向下游执行一个事务的过程中，可能因为网络问题导致执行返回结果出错，但实际数据已经写入到下游，重试时就会出现 Duplicate entry for key ‘PRIMARY’ 的报错。可以测试一下出错后不删除下游 tidb_loader 和下游数据，从新使用 loader 导入，是否可以恢复导入

13

试过，删除不删除数据都可以继续执行，只不过一会还会报错

14

loader也是将文件拉到本地，在本地进行导入的，测试环境应该不用要求网络那么高吧

15

导入的时候有检查下游负载么，loader 使用的并发度是多少？

16

没有增加额外并发，使用的是默认值，导入过程中看磁盘IO只有一个TIKV节点变为50%以上，内存占用70%，cpu占用50%以上，没有到很饱和

17
  1. 检查 loader 的日志 2019/09/25 09:29:45 db.go:125: [error] [exec][sql][USE sale_vip; INSERT INTO xxxxxxxx][error]invalid connection 这种报错会导致数据写入但仍会在 loader 中重试
  2. 后续有很多 2019/09/25 09:29:47 db.go:111: [error] exec sqls[[USE sale_vip; INSERT INTO xxxxxxxx] begin failed dial tcp 127.0.0.1:4000: connect: connection refused 这种报错，是下游数据库连接无法建立，需要检查下游数据库服务是否正常
  3. 可以先检查一下出错时候下游 TiDB 有哪些报错，从 loader 的日志看是下游繁忙导致的
18

这个具体报错看哪里，TIDB的日志？

19

tidb.tar.gz (3.1 MB)
我看现在没有任何操作以及数据写入也在报 [error=“rpc error: code = Canceled desc = grpc: the client connection is closing”]这种error，这次导入是上午9点多导入的

20

loader 的日志和 tidb 日志的时间点不太对的上，两台机器是否有时间差 有尝试过降低 loader 并发度导入么