dm同步binlog出现数据丢失

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

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

【TiDB 版本】：V3.0.14
【问题描述】：dm版本为v1.0.5

背景：通过配置dm组件，从分库分表的多个上游rds同步&汇总数据至下游tidb。

问题现象： tidb中出现偶现少量数据被删除，也即下游tidb中数据丢了

dm相关配置：

filters:
  filter-supported-rule:
    schema-pattern: "pt_order_gxfa_*"
    events: ["all dml", "alter table"]
    action: Do
  filter-unsupported-rule:
    schema-pattern: "*"
    sql-pattern: ["XA PREPARE", "XA START", "XA END", "XA COMMIT", "unsupported-sql", "create database", "drop database", "create table", "drop table", "truncate table", "rename table"]
    action: Ignore

syncers:
  global:
    worker-count: 1
    batch: 100
    max-retry: 100
    safe-mode: true

对应binlog日志如下：
SET @@SESSION.GTID_NEXT= '300faffd-e34b-11e9-8359-b8599f37f8c8:358103310'/*!*/;

    XA START X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1
    INSERT INTO `mt_order_kR0s_619` ...  ((`id` = 1389564502787260468) AND (`buyer_id` = 127194221))
    INSERT INTO `extra_lx8g_311` ... ((`id` = 115915859) AND (`buyer_id` = 127194221))
    XA END X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1
    XA PREPARE X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1
    XA COMMIT X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1


SET @@SESSION.GTID_NEXT= '300faffd-e34b-11e9-8359-b8599f37f8c8:358103312'/*!*/;

    UPDATE `mt_order_kR0s_619` AS `mt_order` SET `update_at` = '2020-06-16 15:41:02.93349' WHERE ((`id` = 1389564502787260468) AND (`buyer_id` = 127194221))    

127191552
127191552

SET @@SESSION.GTID_NEXT= '300faffd-e34b-11e9-8359-b8599f37f8c8:358103313'/*!*/;

    UPDATE `extra_lX8G_311` AS `extra` SET `update_at` = '2020-06-16 15:41:02.945231' WHERE ((`id` = 115915859) AND (`buyer_id` = 127194221))

帮确认问题

1：由于tidb和dm不支持XA事务协议，故dm配置中对XA相关的[ “XA PREPARE”, “XA START”, “XA END” ] 标识进行ignore处理，请问event中 XA START 与 XA END 之间的 insert/update/delete 操作是会被忽略处理，还是被执行呢？

2：在dm中配置忽略 “XA PREPARE”, “XA START”, “XA END” 相关协议，且开启了 safe-mode: true 。

dm上游源rds，当出现XA事务时，业务在事务提交后，主动会执行一次 update 操作(修改某一时间时间字段的值) ，保证tidb在开启safe-mode模式后能最大程度使数据同步至tidb中，不会由于XA事务出现引起数据丢失。但目前的现象是数据在tidb中还是丢了。请问该如何避免和排查定位原因呢？

我们目前的解决方案是：在收到业务方反馈tidb中无该数据时，人肉去上游rds中再执行一次update操作（修改某一时间时间字段的值），然后tidb中该数据即可正常复原。但此方案需要依赖业务方反馈来修复，比较滞后；如果没反馈可能存在tidb中数据与rds中数据不一致的现象。

多谢

yilong · 2020 年6 月 19 日 02:12

麻烦上传一个XA事务对应的完整dm-worker日志，多谢。

qq悟空 · 2020 年6 月 19 日 07:06

好的，如附件


143124:[2020/06/16 15:41:02.928 +08:00] [ERROR] [common.go:35] ["parse statement"] [sql="XA START X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1"] [error="line 1 column 2 near \"XA START X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1\" "]
143125:[2020/06/16 15:41:02.928 +08:00] [ERROR] [common.go:35] ["parse statement"] [sql="XA END X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1"] [error="line 1 column 2 near \"XA END X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1\" "]
143126:[2020/06/16 15:41:02.934 +08:00] [ERROR] [common.go:35] ["parse statement"] [sql="XA COMMIT X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1"] [error="line 1 column 2 near \"XA COMMIT X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1\" "]
143127:[2020/06/16 15:41:02.991 +08:00] [WARN] [syncer.go:1604] ["skip event"] [task=prod_order_dm] [unit="binlog replication"] [event=query] [statement="XA START X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1"] [schema=pt_order_hwh1_0077]
143128:[2020/06/16 15:41:02.992 +08:00] [WARN] [syncer.go:1604] ["skip event"] [task=prod_order_dm] [unit="binlog replication"] [event=query] [statement="XA END X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1"] [schema=pt_order_hwh1_0077]
143129:[2020/06/16 15:41:02.992 +08:00] [WARN] [syncer.go:1604] ["skip event"] [task=prod_order_dm] [unit="binlog replication"] [event=query] [statement="XA COMMIT X'647264732d313063393735386238303738623030314070745f6f72646572',X'50545f4f524445525f313538333438383832303437385a5a4a535f424353525f30303737',1"] [schema=pt_order_hwh1_0077]

dm-worker.log.zip (3.0 MB)

感谢 ~~

zhenjiaogao · 2020 年6 月 19 日 07:40

收到，这里分析下，如有进度会跟帖回复~~

qq悟空 · 2020 年6 月 19 日 07:41

好的感谢

luancheng-PingCAP · 2020 年6 月 19 日 08:18

1: XA START 和 XA END 之间的 dml 操作会被执行。

能否上传一条丢失的数据，以及对应这条数据对应的 Binlog Event，和前后一段时间的 Binlog Event，我们好排查一下

qq悟空 · 2020 年6 月 19 日 08:50

好的，附件太大，网盘地址见私信(网盘文件有效期24小时) ，感谢

tidb中丢失的数据为 ：
select pid,id,buyer_id,create_at,update_at from mt_order where id = 1389564502787260468 and buyer_id=127194221;
+-----------+---------------------+-----------+---------------------+---------------------+
| pid       | id                  | buyer_id  | create_at           | update_at           |
+-----------+---------------------+-----------+---------------------+---------------------+
| 285563777 | 1389564502787260468 | 127194221 | 2020-06-16 14:48:18 | 2020-06-16 15:41:04 |
+-----------+---------------------+-----------+---------------------+---------------------+


下游tidb中表结构为：
CREATE TABLE `mt_order` (
  `pid` bigint(20) unsigned NOT NULL ,
  `id` bigint(20) unsigned NOT NULL ,
  `union_order` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `flag` tinyint(4) NOT NULL DEFAULT '0' ,
  `buyer_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `recv_mobile` varchar(20) NOT NULL DEFAULT '' ,
  `mall_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `goods_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `goods_icon` varchar(200) NOT NULL DEFAULT '' ,
  `goods_sku_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `goods_spec_desc` varchar(128) NOT NULL DEFAULT '' ,
  `goods_snap_id` char(128) NOT NULL DEFAULT '' ,
  `goods_group_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `goods_group_size` int(10) unsigned NOT NULL DEFAULT '1' ,
  `out_sku_sn` varchar(100) DEFAULT '' ,
  `goods_unit_price` int(10) unsigned NOT NULL DEFAULT '1' ,
  `goods_quantity` int(11) unsigned NOT NULL DEFAULT '1' ,
  `goods_ship_limit_seconds` int(10) unsigned NOT NULL DEFAULT '24' ,
  `goods_cat_id` int(11) NOT NULL DEFAULT '0' ,
  `success_time` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `pay_success_time` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `process_status` int(11) unsigned NOT NULL DEFAULT '0' ,
  `finished_status` int(11) unsigned NOT NULL DEFAULT '0' ,
  `finish_on_refund_end` tinyint(4) NOT NULL DEFAULT '0' ,
  `refund_status` int(11) unsigned NOT NULL DEFAULT '0' ,
  `lock_status` int(11) unsigned NOT NULL DEFAULT '0' ,
  `lucky_draw_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `lucky_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `group_order_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `group_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `ship_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `buyer_remark` varchar(512) NOT NULL DEFAULT '' ,
  `recv_type` tinyint(4) NOT NULL DEFAULT '0' ,
  `auto_sign` tinyint(4) NOT NULL DEFAULT '0' ,
  `forbid_refund` tinyint(4) NOT NULL DEFAULT '0' ,
  `address_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `address_snap_id` char(128) NOT NULL DEFAULT '' ,
  `custom_addr_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `mall_confirm_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `mall_confirm_time` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `buyer_confirm_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `buyer_confirm_time` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `buyer_confirm_delay_count` tinyint(4) NOT NULL DEFAULT '0' ,
  `review_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `buyer_review_count` tinyint(4) NOT NULL DEFAULT '0' ,
  `payment_deadline` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ,
  `payment_money_type` tinyint(4) NOT NULL DEFAULT '0' ,
  `payment_total` int(10) unsigned NOT NULL DEFAULT '0' ,
  `payment_express` int(10) unsigned NOT NULL DEFAULT '0' ,
  `payment_system_discount` int(10) unsigned NOT NULL DEFAULT '0' ,
  `payment_activity_discount` int(10) unsigned NOT NULL DEFAULT '0' ,
  `payment_mall_discount` int(10) unsigned NOT NULL DEFAULT '0' ,
  `mall_coins_discount` int(10) unsigned NOT NULL DEFAULT '0' ,
  `system_coins_discount` int(10) unsigned NOT NULL DEFAULT '0' ,
  `payment_cash_card` int(11) unsigned NOT NULL DEFAULT '0' ,
  `payment_method` tinyint(4) NOT NULL DEFAULT '0' ,
  `payment_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `coupon_desc` varchar(128) NOT NULL DEFAULT '' ,
  `activity_desc` varchar(128) NOT NULL DEFAULT '' ,
  `logistic_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `aftersale_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `activity_type` int(11) NOT NULL DEFAULT '0' ,
  `activity_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `activity_snap_id` char(128) NOT NULL DEFAULT '' ,
  `invite_from_attender_id` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `is_hide` tinyint(4) NOT NULL DEFAULT '0' ,
  `is_deleted` tinyint(4) NOT NULL DEFAULT '0' ,
  `is_bot` tinyint(4) NOT NULL DEFAULT '0' ,
  `platform` tinyint(3) unsigned NOT NULL DEFAULT '0' ,
  `subsidy` int(10) unsigned NOT NULL DEFAULT '0' ,
  `mod_subsidy` int(10) unsigned NOT NULL DEFAULT '0' ,
  `ext_goods_id` varchar(50) NOT NULL DEFAULT '' ,
  `seq` bigint(20) unsigned NOT NULL DEFAULT '0' ,
  `client_ip` varchar(64) NOT NULL DEFAULT '' ,
  `device` varchar(200) NOT NULL DEFAULT '' ,
  `sign_reward_coin` int(10) unsigned NOT NULL DEFAULT '0' ,
  `create_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  `update_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `payment_fee` int(10) unsigned NOT NULL DEFAULT '0' ,
  `service_fee` int(10) unsigned NOT NULL DEFAULT '0' ,
  `td` bigint(20) NOT NULL DEFAULT '0' ,
  UNIQUE KEY `uk_pid` (`pid`),
  KEY `idx_id` (`id`),
  KEY `sd_status` (`ship_deadline`,`process_status`),
  KEY `ucd_status` (`buyer_confirm_deadline`,`process_status`),
  KEY `pd_status` (`payment_deadline`,`process_status`),
  KEY `create_at` (`create_at`),
  KEY `goods_recv_mobile_status` (`goods_id`,`recv_mobile`,`process_status`),
  KEY `seq` (`seq`),
  KEY `activity` (`activity_id`),
  KEY `buyer_id` (`buyer_id`),
  KEY `mall_id` (`mall_id`,`success_time`),
  KEY `group_order_id` (`group_order_id`),
  KEY `ext_goods_id` (`ext_goods_id`),
  KEY `recv_mobile` (`recv_mobile`),
  KEY `mall_status_success` (`mall_id`,`process_status`,`success_time`,`is_bot`),
  KEY `union_order` (`union_order`),
  KEY `mallid_update_at` (`mall_id`,`update_at`),
  KEY `update_at` (`update_at`),
  KEY `order_rds_mid_create_at` (`mall_id`,`is_bot`,`is_deleted`,`create_at`),
  KEY `order_rds_mid_success_time` (`mall_id`,`is_bot`,`is_deleted`,`success_time`),
  KEY `order_rds_mid_ship_deadline` (`mall_id`,`is_bot`,`is_deleted`,`ship_deadline`),
  KEY `order_rds_mid_confirm_time` (`mall_id`,`is_bot`,`is_deleted`,`buyer_confirm_time`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin/*!90000 SHARD_ROW_ID_BITS=4 */ COMMENT=''

zhenjiaogao · 2020 年6 月 19 日 10:00

收到，这里分析下，如有进度会尽快跟帖回复，感谢~~

luancheng-PingCAP · 2020 年6 月 19 日 14:17

我看到 binlog 中这条数据：
在 15:41:02 时有 insert 和 update 操作，是说同步到这里的时候，下游 tidb 并没有数据，然后在 15:57 的时候，上游手动触发 update 下游才有了数据。
会不会是延迟问题，比如上游触发 update 后，实际上是第一批 insert 和 update 才同步到 tidb。可以在 dm-worker 日志中确认下，不过我看 dm-worker 的日志时间点貌似和这个 binlog 对不上

qq悟空 · 2020 年6 月 22 日 03:51

没有同步延迟的现象和问题，除了这条数据异常外其他数据同步均正常的，并且这个问题是偶现的，不是100%出现。

在 15:41:02 时有 insert 和 update 操作，是说同步到这里的时候，下游 tidb 并没有数据，-- 是的，tidb中没有数据后业务方会找到db来排查原因。

在 15:57 的时候，上游手动触发 update 下游才有了数据。 – 根据业务方反馈定位到具体的id后，在上游数据源中执行了一次update操作，触发数据更新和同步( safe-mode: true ) ，这个时候这个数据在下游tidb中就有了

luancheng-PingCAP · 2020 年6 月 22 日 04:08

我理一下，一条数据同样的 update 操作，在 15:41:02 触发没有同步，在 15:57 触发就同步了。看起来不像是 DM 忽略的问题。

如果再出现这个问题，可否在 15:41 至 15:57 的时间范围内，确认下 checkpoint 里面的 binlog_pos 和 gtid 同步到哪里了，是否同步到了第一个 update 操作？

qq悟空 · 2020 年6 月 22 日 05:24

同一个id一般不会再出现。再出现的是其他的id。

checkpoint 里面的 binlog_pos 和 gtid 只会记录最新位置吧，如果异常后去查看这个表确认，应该是找不到历史记录了，请问历史位置在哪里可以看到呢？

感谢

luancheng-PingCAP · 2020 年6 月 22 日 05:56

是的，现在要确认一点。

就是当发现数据丢失后，看下此时 checkpoint 里面的 binlog_pos，记作 pos_a, 是否大于 mysql 里面的该条丢失数据的 binlog_pos, 记作 pos_b。

如果 pos_a > pos_b，此时数据丢失，那应该是 DM 的 bug.
如果 pos_a < pos_b, 那说明数据没有同步到，需要看看是什么其它问题。

qq悟空 · 2020 年6 月 22 日 05:59

好的。再出现该类问题后，根据这个排查一下，多谢

来了老弟 · 2020 年6 月 22 日 07:00

qq悟空 · 2020 年6 月 22 日 12:18

如下图：id=1396568855326802017的数据行

在2020-06-22 19:43:31时刻，上游rds中出现数据更新，但下游tidb中并未出现该行数据，通过checkpoint表排除了dm同步延迟的嫌疑。

在2020-06-22 20:03:18时刻，人肉在上游rds中，对该数据行触发一次更新操作，下游tidb中出现了该行数据

帮再确认下问题排查方向及原因，感谢

luancheng-PingCAP · 2020 年6 月 22 日 15:37

看代码 update_time 实时不能确定 dm 同步无延迟吧

https://github.com/pingcap/dm/blob/e1c5376b4d3d31c353c6431d3eb9e91dc0608105/syncer/checkpoint.go#L765

最好能确认下 binlog 里 pos 95654467 和 97806123 之间有几次 update 这个 ID 的操作。

qq悟空 · 2020 年6 月 23 日 09:09

update_time时间有在进行更新，可以说明dm任务同步没有出现异常以及没有出现同步延迟吧

缘由是：上游源rds中该表数据出现修改，在下游tidb中的checkpoint表里该表的update_time字段也跟着更新的话，说明这个表的dm同步任务至少是正常的，对吧？但不能证实这一行的数据同步是正常的？

id=1396568855326802017 问题出现时间点是 2020-06-22 19:43:31

通过分析binlog ，该行数据在 2020-06-22 19:00:00 到 2020-06-22 21:00:00 之间一共有3次操作，如下

    第一次为XA事务之间的insert，binlog位置和时间点分别为 #start 93302580 end 93306096 time 2020-06-22 19:43:31
    XA START X
    INSERT INTO `pt_order_hwh1_0008`.`mt_order_kr0s_070`()
    XA COMMIT X

    第二次为XA事务提交之后，业务侧主动触发的一次update操作，binlog位置和时间点分别为 #start 93307686 end 93309234 time 2020-06-22 19:43:31
    UPDATE `pt_order_hwh1_0008`.`mt_order_kr0s_070`

    第三次为第三方反馈tidb中无该行数据后，人肉在上游rds中触发的一次update操作，binlog位置和时间点分别为 #start 97804556 end 97806123 time 2020-06-22 20:03:18
    UPDATE `pt_order_hwh1_0008`.`mt_order_kr0s_070`

pos.sql (11.5 KB)

pos.sql文件为该行数据在这个时间段内的3次变更日志

背景：由于tidb及dm不支持mysql的XA事务协议，所以当初业务确认的方案是：在出现XA事务时，主动在XA事务提交后触发一次数据行的update操作，避免该行数据无法完整同步到下游tidb中。目前来看，还是会有一小部分数据行在业务主动触发update操作后依然无法出现在tidb中，现象是tidb中没有该行数据。临时补救措施是：人肉再去上游rds中触发一次update操作，这时tidb中该行数据即可正常出现了

binlog文件由于太大，无法上传。烦请大佬帮分析下数据丢失的原因，感谢 ~

csuzhangxc-PingCAP · 2020 年6 月 23 日 10:29

你好，请问可以执行一下以下一些操作吗？

mt_order 大概有多少数据量？如果 1 亿行之内的话，可以执行一下 ADMIN CHECK TABLE mt_order 看看
DM task 的 safe-mode 之前是为什么要设置为 true，能否置为 false
TiDB 上能否接受开 general log？如果可以的话，开一下 general log
如果之后还出现这种数据丢失现象的话，能否用 HTTP API 拿一下这个 uk_pid 的 MVCC（https://docs.pingcap.com/zh/tidb/v3.0/tidb-control#base64decode-命令），同时提供一下对应时间段内的 DM 与 TiDB log

qq悟空 · 2020 年6 月 23 日 11:01

可以的，不过帮确认下

1: mt_order表行数有2亿+ ，这个admin check table table_name执行后会有什么影响呢？执行该操作目的是什么呢？

2: safe-mode打开是因为dm同步数据导入下游tidb时，会出现唯一索引冲突(表中没有主键)，tidb下游只有dm会写入数据，其他业务都是只读操作，之前asktug反馈过这个问题，建议打开safe-mode来避免该问题

3: 目前该tidb集群有3个tidb节点，一个tidb节点为dm同步导入数据使用，另外2个tidb为业务只读场景使用。 general log 是全局3个tidb都要打开吗？是否支持只在dm同步导入数据使用的这个tidb节点里打开general log呢？另外2个只读节点不开 general log

4: log可以提供的。使用这个http api，需要哪些前置条件吗？比如默认的gc时间是否需要调大等？