dm同步binlog出现数据丢失

csuzhangxc-PingCAP · 2020 年6 月 23 日 12:59

执行过程中主要是对性能会有一些影响，可以尝试找业务低峰期进行；目的是排除数据与索引间可能存在的不一致等
这个是单张表同步到 TiDB，不是多张表合并吧。有当时唯一索引冲突的 askTUG 反馈链接吗？如果上游不是多表合并，有唯一键应该也是要能保证不产生冲突的
只需要 DM 连接的节点打开 general log 即可
哦，你这个场景有些特别，发现时可能已经过了默认的 10 分钟 GC 时间很久了，而且也不是很好调整一个明确的值。可以在发现问题后，使用这个 HTTP API 尝试获取最新的一个 MVCC 版本也有帮助

qq悟空 · 2020 年6 月 24 日 02:35

感谢确认

1 低峰期我试一下看看
2 是分库分表合并，上游有12个rds96个分库768个分表
3 这个日志我尝试打开一下
4 我尝试下看看结果

yilong · 2020 年6 月 24 日 05:55

好的，有问题请继续反馈，多谢。

qq悟空 · 2020 年6 月 29 日 06:56

用 HTTP API 获取数据的MVCC数据时发现有些异常，如下图，获取行数据时拿不到具体的值，帮确认下

**curl "http://$IP:10080/mvcc/index/test/t/a/1?a=1"**
test=库名
t=表名
第一个a=唯一索引名称
第一个1=唯一索引字段的值？
第二个a=唯一索引字段名称
第二个1=唯一索引字段的值？

**curl "http://$IP:10080/mvcc/key/test/t/1"**
test=库名
t=表名
1=唯一索引字段值

yilong · 2020 年6 月 29 日 08:52

请参考这里对比下
https://github.com/pingcap/tidb/blob/master/docs/tidb_http_api.md

qq悟空 · 2020 年6 月 29 日 11:18

好的多谢我试一下

qq悟空 · 2020 年6 月 29 日 11:40

大佬：先从第三个和第四个操作进行了确认，如下：

grep 299101847 tidb.log < general log >

[2020/06/29 18:01:47.246 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=169] [user=tidb_dm_user@192.168.17.149] [schemaVersion=215] [txnStartTS=417706778874871814] [current_db=] [sql="REPLACE INTO `pt_order`.`mt_order` (`pid`,`id`,`union_order`,`flag`,`buyer_id`,`recv_mobile`,`mall_id`,`goods_id`,`goods_icon`,`goods_sku_id`,`goods_spec_desc`,`goods_snap_id`,`goods_group_id`,`goods_group_size`,`out_sku_sn`,`goods_unit_price`,`goods_quantity`,`goods_ship_limit_seconds`,`goods_cat_id`,`success_time`,`pay_success_time`,`process_status`,`finished_status`,`finish_on_refund_end`,`refund_status`,`lock_status`,`lucky_draw_id`,`lucky_deadline`,`group_order_id`,`group_deadline`,`ship_deadline`,`buyer_remark`,`recv_type`,`auto_sign`,`forbid_refund`,`address_id`,`address_snap_id`,`custom_addr_id`,`mall_confirm_deadline`,`mall_confirm_time`,`buyer_confirm_deadline`,`buyer_confirm_time`,`buyer_confirm_delay_count`,`review_deadline`,`buyer_review_count`,`payment_deadline`,`payment_money_type`,`payment_total`,`payment_express`,`payment_system_discount`,`payment_activity_discount`,`payment_mall_discount`,`mall_coins_discount`,`system_coins_discount`,`payment_cash_card`,`payment_method`,`payment_id`,`coupon_desc`,`activity_desc`,`logistic_id`,`aftersale_id`,`activity_type`,`activity_id`,`activity_snap_id`,`invite_from_attender_id`,`is_hide`,`is_deleted`,`is_bot`,`platform`,`subsidy`,`mod_subsidy`,`ext_goods_id`,`seq`,`client_ip`,`device`,`sign_reward_coin`,`create_at`,`update_at`,`payment_fee`,`service_fee`,`td`) VALUES ('299101847','1407064716871811163','0',1,'19502354','18875319294','140088','41182287','oss/1/202005/f89107659f1d5d7d-4626x3084.jpg','1341848979','','1592805240751830151-95326841','0',0,'',3200,1,172800,22140,'2020-06-28 16:33:13','2020-06-28 16:33:13',4,0,0,0,0,'0','0000-00-00 00:00:00','0','0000-00-00 00:00:00','2020-07-01 00:35:00','',0,0,0,'75618277','1593333192804784128-95694046','0','0000-00-00 00:00:00','0000-00-00 00:00:00','0000-00-00 00:00:00','0000-00-00 00:00:00',0,'0000-00-00 00:00:00',0,'2020-06-28 17:03:12',0,0,0,3200,0,0,0,0,0,0,'0','平台券[无门槛券]','','0','0',0,'0','','0',0,0,0,8,0,0,'','0','223.104.48.31','',0,'2020-06-28 16:33:12','2020-06-29 00:35:00',20,1300,20200628)"]
[2020/06/29 18:01:47.248 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=169] [user=tidb_dm_user@192.168.17.149] [schemaVersion=215] [txnStartTS=417706778874871814] [current_db=] [sql="DELETE FROM `pt_order`.`mt_order` WHERE `pid` = '299101847' LIMIT 1"]
[2020/06/29 18:01:47.249 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=232] [user=tidb_dm_user@192.168.17.150] [schemaVersion=215] [txnStartTS=417706778874871816] [current_db=] [sql="DELETE FROM `pt_order`.`mt_order` WHERE `pid` = '299101847' LIMIT 1"]
[2020/06/29 18:01:47.249 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=169] [user=tidb_dm_user@192.168.17.149] [schemaVersion=215] [txnStartTS=417706778874871814] [current_db=] [sql="REPLACE INTO `pt_order`.`mt_order` (`pid`,`id`,`union_order`,`flag`,`buyer_id`,`recv_mobile`,`mall_id`,`goods_id`,`goods_icon`,`goods_sku_id`,`goods_spec_desc`,`goods_snap_id`,`goods_group_id`,`goods_group_size`,`out_sku_sn`,`goods_unit_price`,`goods_quantity`,`goods_ship_limit_seconds`,`goods_cat_id`,`success_time`,`pay_success_time`,`process_status`,`finished_status`,`finish_on_refund_end`,`refund_status`,`lock_status`,`lucky_draw_id`,`lucky_deadline`,`group_order_id`,`group_deadline`,`ship_deadline`,`buyer_remark`,`recv_type`,`auto_sign`,`forbid_refund`,`address_id`,`address_snap_id`,`custom_addr_id`,`mall_confirm_deadline`,`mall_confirm_time`,`buyer_confirm_deadline`,`buyer_confirm_time`,`buyer_confirm_delay_count`,`review_deadline`,`buyer_review_count`,`payment_deadline`,`payment_money_type`,`payment_total`,`payment_express`,`payment_system_discount`,`payment_activity_discount`,`payment_mall_discount`,`mall_coins_discount`,`system_coins_discount`,`payment_cash_card`,`payment_method`,`payment_id`,`coupon_desc`,`activity_desc`,`logistic_id`,`aftersale_id`,`activity_type`,`activity_id`,`activity_snap_id`,`invite_from_attender_id`,`is_hide`,`is_deleted`,`is_bot`,`platform`,`subsidy`,`mod_subsidy`,`ext_goods_id`,`seq`,`client_ip`,`device`,`sign_reward_coin`,`create_at`,`update_at`,`payment_fee`,`service_fee`,`td`) VALUES ('299101847','1407064716871811163','0',1,'19502354','18875319294','140088','41182287','oss/1/202005/f89107659f1d5d7d-4626x3084.jpg','1341848979','','1592805240751830151-95326841','0',0,'',3200,1,172800,22140,'2020-06-28 16:33:13','2020-06-28 16:33:13',4,0,0,0,0,'0','0000-00-00 00:00:00','0','0000-00-00 00:00:00','2020-07-01 00:35:00','',0,0,0,'75618277','1593333192804784128-95694046','0','0000-00-00 00:00:00','0000-00-00 00:00:00','0000-00-00 00:00:00','0000-00-00 00:00:00',0,'0000-00-00 00:00:00',0,'2020-06-28 17:03:12',0,0,0,3200,0,0,0,0,0,0,'0','平台券[无门槛券]','','0','0',0,'0','','0',0,0,0,8,0,0,'','0','223.104.48.31','',0,'2020-06-28 16:33:12','2020-06-29 18:01:47',20,1300,20200628)"]
[2020/06/29 18:01:51.216 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=7, indexValues={41182287, 18875319294, 4, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.218 +08:00] [WARN] [session.go:478] [sql] [conn=169] [label=general] [error="[kv:9007]Write conflict, txnStartTS=417706778874871814, conflictStartTS=417706778874871816, conflictCommitTS=417706778874871816, key={tableID=373, indexID=7, indexValues={41182287, 18875319294, 4, 8646911284909531940, }} primary={tableID=373, indexID=1, indexValues={299101847, }} [try again later]"] [txn="Txn{state=invalid}"]
[2020/06/29 18:01:51.220 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=1, indexValues={299101847, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871814, ttl: 3004, type: Put"]
[2020/06/29 18:01:51.221 +08:00] [WARN] [session.go:678] [retrying] [conn=169] [schemaVersion=215] [retryCnt=0] [queryNum=2] [sql="DELETE FROM `pt_order`.`mt_order` WHERE `pid` = '299101847' LIMIT 1"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=11, indexValues={140088, 1848367592629075968, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=5, indexValues={1848367629119520768, 4, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=8, indexValues={0, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=3, indexValues={1848372542360780800, 4, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=15, indexValues={140088, 4, 1848367592629075968, 0, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=12, indexValues={0, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=22, indexValues={140088, 0, 0, 0, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=13, indexValues={, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=16, indexValues={0, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=4, indexValues={0, 4, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.223 +08:00] [INFO] [lock_resolver.go:487] ["resolveLock rollback"] [lock="key: {tableID=373, indexID=9, indexValues={0, 8646911284909531940, }}, primary: {tableID=373, indexID=1, indexValues={299101847, }}, txnStartTS: 417706778874871816, ttl: 3001, type: Del"]
[2020/06/29 18:01:51.656 +08:00] [WARN] [session.go:478] [sql] [conn=232] [label=general] [error="[kv:9007]Write conflict, txnStartTS=417706778874871816, conflictStartTS=417706779923447809, conflictCommitTS=417706779923447812, key={tableID=373, indexID=1, indexValues={299101847, }} primary={tableID=373, indexID=1, indexValues={299101847, }} [try again later]"] [txn="Txn{state=invalid}"]
[2020/06/29 18:01:51.657 +08:00] [WARN] [session.go:678] [retrying] [conn=232] [schemaVersion=215] [retryCnt=0] [queryNum=1] [sql="DELETE FROM `pt_order`.`mt_order` WHERE `pid` = '299101847' LIMIT 1"]


pid为表mt_order唯一索引，库名为pt_order ，相关mvcc数据入下几图

从general log时间线来看，是REPLACE INTO语句先执行，DELETE语句后执行。
dm同步工具里打开safe-mode后，上游的UPDATE语句改写后，在下游的执行顺序应该是先DELETE后REPLACE吧，帮确认下是sql执行顺序错乱引起的数据丢失吗？

上游是多个rds，合库合表到下游tidb中；如果某个rds在t时刻对主键pid=1进行了删除操作，另一个rds也在t时刻后对pid=1进行了insert操作，那么使用dm做合库合表增量同步时，会出现insert操作先到达tidb+delete操作后到达tidb这个现象吗？如果是的话，之前未开启safe-mode设置时出现的唯一索引冲突应该是这个原因引起的

csuzhangxc-PingCAP · 2020 年6 月 29 日 12:24

请问能提供一下这个范围内的 tidb log吗？general log和该时间范围内的其他log最好都提供一下

qq悟空 · 2020 年6 月 29 日 12:32

好的，我整理下

qq悟空 · 2020 年6 月 29 日 14:58

如下，上游rds的binlog、dm-worker的log和配置文件，以及tidb和general log

链接: https://pan.baidu.com/s/18GsuiPhhleU5xn9gvJojXg 
提取码: jpq4

辛苦大佬帮确认下问题，感谢

WangXiangUSTC · 2020 年6 月 30 日 06:46

上游是多个rds，合库合表到下游tidb中；如果某个rds在t时刻对主键pid=1进行了删除操作，另一个rds也在t时刻后对pid=1进行了insert操作，那么使用dm做合库合表增量同步时，会出现insert操作先到达tidb+delete操作后到达tidb这个现象吗？如果是的话，之前未开启safe-mode设置时出现的唯一索引冲突应该是这个原因引起的

是的，各个分表 dml 的同步是独立的，如果各个分表含有同样主键的数据，会出现数据冲突的现象。麻烦确认下各个分表是否包含相同的主键。另外，我在 tidb 的 general 日志中没搜到上面描述中出现问题的数据 1396568855326802017，能否提供一条丢失数据的主键值，我再确认下

qq悟空 · 2020 年6 月 30 日 08:26

上游各个分表的主键都是pid字段，id字段是唯一索引；下游tidb中对应表没有主键，pid是唯一索引，id是普通索引。

下游mt_order表没有主键，只有唯一索引字段pid 。

最新的附件里提供的这些日志，对应的记录的pid值是 299101847 ， id 是 1407064716871811163 。

id=1396568855326802017 的记录是最早反馈问题时的记录，当时没抓取数据的mvcc数据，也没开启general log ，请忽略这个记录的排查。以最新的各种日志都有的 pid=299101847 ，id=1407064716871811163 这一条记录进行排查。

#上游rds分表结构#
CREATE TABLE `mt_order_kr0s_650` (
  `pid` bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT 'drds生成全局唯一id',
  `id` bigint(20) unsigned NOT NULL COMMENT '业务生成雪花id',
........
.......
  PRIMARY KEY (`pid`),
  UNIQUE KEY `uk_id` (`id`),



#下游tidb合表结构#
CREATE TABLE `mt_order` (
  `pid` bigint(20) unsigned NOT NULL COMMENT 'drds生成全局唯一id',
  `id` bigint(20) unsigned NOT NULL COMMENT '业务生成雪花id',
......
......
  UNIQUE KEY `uk_pid` (`pid`),
  KEY `idx_id` (`id`),

WangXiangUSTC · 2020 年6 月 30 日 08:48

从日志中可以看到下面这些日志(去掉了数据)：


[2020/06/29 18:01:47.246 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=169] [user=tidb_dm_user@192.168.17.149] [schemaVersion=215] [txnStartTS=417706778874871814] [current_db=] [sql="REPLACE INTO ......]

[2020/06/29 18:01:47.248 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=169] [user=tidb_dm_user@192.168.17.149] [schemaVersion=215] [txnStartTS=417706778874871814] [current_db=] [sql="DELETE FROM `pt_order`.`mt_order` WHERE `pid` = '299101847' LIMIT 1"]

[2020/06/29 18:01:47.249 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=232] [user=tidb_dm_user@192.168.17.150] [schemaVersion=215] [txnStartTS=417706778874871816] [current_db=] [sql="DELETE FROM `pt_order`.`mt_order` WHERE `pid` = '299101847' LIMIT 1"]

[2020/06/29 18:01:47.249 +08:00] [INFO] [session.go:1977] [GENERAL_LOG] [conn=169] [user=tidb_dm_user@192.168.17.149] [schemaVersion=215] [txnStartTS=417706778874871814] [current_db=] [sql="REPLACE INTO ......]

可以看出有两个客户端同时在对这同一行数据做处理，分别在 192.168.17.149 和 192.168.17.150，麻烦确认下是否在这两个服务器上部署了两个 DM-worker，可能的原因：

这两个 DM-worker 同步的是同一个合库合表的任务，但是分表中包含主键相同的数据，在合库时会互相干扰
创建了多个任务，这多个任务都同步这个表，同步任务之间互相干扰

麻烦先查一下

qq悟空 · 2020 年6 月 30 日 09:21

是的。192.168.17.149 和 192.168.17.150 上有多个rds的dm-worder任务。

下面是这一行数据，在上游大致的执行逻辑

第一个事务：由于mt_order表是根据buyer_id进行分库分表，所以不同的buyer_id值（比如a和b），会存在不同的rds中，在使用dm同步到下游时，会通过不同的dm-worker任务进行同步

    XA START ...
       delete from mt_order where pid = 299101847 and buyer_id = a;
       INSERT INTO mt_order(pid,buyer_id...) values(299101847,b);
    XA END ...
    XA PREPARE ...
    XA COMMIT ...

第二个事务(会紧接第一个事务执行并提交)
    update  mt_order  set  update_at =  now() where pid = 299101847 and buyer_id = b;

下游tidb的general log出现2次delete操作与2次replace操作，应该是由于开启了dm的safe-mode参数造成的。

上游rds中业务进行第二个事务的原因是： dm不支持XA协议，担心会过滤和忽略第一个事务里的delete和insert操作，实施的补丁。最开始没有这个补丁措施时，有发现数据被dm忽略同步的情况，当时确认的原因是：第一个事务里的delete操作被某一个dm-worker后执行，insert操作被另一个dm-worker后执行导致的。

辛苦大佬再帮确认下感谢

WangXiangUSTC · 2020 年6 月 30 日 09:31

一个 dm-worker 执行了：
replace into
delete
replace into
这个应该对应你们的业务：先写入，补偿操作 update

另一个 dm-worker 执行了：
delete

主要是第二个 dm-worker 为什么执行了 delete，这个应该不符合预期把，需要查一下

qq悟空 · 2020 年6 月 30 日 10:04

第二个 dm-worker里的delete操作，是上游第一个事务(分布式XA事务)里执行的第一个sql，这个是正常的业务逻辑，正常情况下是应该最先被执行的，否则后面的逻辑都会出错。这个delete的出发点是：上游分库分表的buyer_id字段值不能更新，现在有一个业务场景是需要更新这个分库分表字段的值，目前的策略是先删除pid = 299101847 and buyer_id = a这一行记录，再写入 pid = 299101847 and buyer_id = b这一行记录，其他字段的值保持不变。

如果业务上不做补偿操作update，还是会有一定概率出现上游分布式XA事务里原本应该先执行的delete操作，在下游的某个dm-worker里落后于另一个dm-worker的insert操作，在tidb里变成：replace into 先执行， delete后执行，以至数据出现了丢失的现象。

大佬帮看看，有啥好的解决办法吗？多谢

WangXiangUSTC · 2020 年6 月 30 日 10:23

我确认下信息啊，

目前的策略是先删除pid = 299101847 and buyer_id = a这一行记录，再写入 pid = 299101847 and buyer_id = b这一行记录

这个操作是在同一个分表中执行，还是说在分表 1 中删除，然后在分表2中再写入？

qq悟空 · 2020 年6 月 30 日 10:41

业务是通过一个proxy地址来操作没有分库也没有分表的表名mt_order，删除和写入操作都是这个表名，业务不会接触到具体的分库和分表名称。proxy会负责根据buyer_id的值路由到具体的某一个rds实例上。我们这里使用的是阿里云的drds服务。

对业务侧来说是一个事务里2个操作（先是1个delete操作+后是1个insert操作），proxy地址（也就是drds）会把这2个操作拆出分布式事务，路由分发到2个对应的rds实例上某分库某分表内进行执行。

WangXiangUSTC · 2020 年6 月 30 日 11:05

好的，那问题应该比较明确了，是不同的分表操作了同一个主键的数据，DM 无法处理这种场景。

现在的主要问题是你们的补偿机制有时候也没有生效对吧，需要完善下你们的补偿机制。想问下：

你们在业务的事务提交后，主动执行一次 update 操作(修改某一时间时间字段的值) 这个操作是在业务的事务提交后多久执行的？
补偿机制能否加一个自动验证的步骤，比如执行后去下游 TiDB 确认，如果没有则再次 update。
或者能改一下 proxy 的规则，比如使用 pid 来区分？

qq悟空 · 2020 年6 月 30 日 11:47

1：目前补偿的update操作，是在分布式事务提交后就进行的。有些时候生效了，有些时候没有生效。目前考虑在分布式事务提交1分钟后再进行补偿update，但不确认是否完全有效解决该问题，这个业务改动上成本有点高

2：这种补偿机制可以考虑，但最好是放在业务逻辑外部解耦处理，需要订阅相关的修改事件来触发

3：这个方法目前不太可行。

感谢