多种方式告诉你如何计算 DM 同步数据到 TiDB 的延时时间

作者： hey-hoho 原文来源：https://tidb.net/blog/71160ee2

【是否原创】是

【首发渠道】TiDB 社区

背景

用户在做技术选型的过程中，总是会对一些数据指标比较关心，特别是在和竞品相比较的时候，更加需要一些有说服力的数据。基于 MySQL 开发的项目在迁移到 TiDB 的时候，使用 DM 同步数据是必不可少的一个环节，我在最近的一次 POC 中就碰到了这样一个需求，需要评估一个具体的延时时间参考值，因为用户在迁移前期的过渡阶段是把 TiDB 作为 MySQL 的从库，有些场景对这个延时很敏感，如果延时太大会直接影响业务。

由于 DM 并不能直接看到整个链路的延时时间，所以我们必须另辟蹊径找一些办法来实现，以下是我实践过的几种办法，也希望能抛砖引玉，带出其他大佬给社区带来更好的方案。

我的思路比较简单，就是分别根据上下游事务的某个时间点来计算时间差，这个时间差应该要精确到毫秒级，可以从三个方向入手：

• Binlog Position

• TiDB General log

• SQL 自动记录时间

接下来就分别看一下如何实现。

基于 Binlog Position

DM 增量同步是基于订阅 MySQL Binlog 来实现的，所以首先考虑的办法就是通过 Binlog Position 来定位某一个事务，只要分别找到同一个 Position 在 Binlog 和 DM-Worker Log 中记录的时间，就可以大致计算出这个时间差。

我使用如下一张测试表来演示这个过程：

CREATE TABLE `table1` (  `id` int(11) NOT NULL,  `mysql_created` timestamp(3) NOT NULL DEFAULT CURRENT_TIMESTAMP(3),  PRIMARY KEY (`id`)) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin

在 DM Task 完全启动成功之后，我们往 MySQL 里的 table1 插入一条数据：

insert into table1 values(1,null);

插入成功后我们找到这个事务第一个 events 的 position，这个示例中是 1422：

接下来去 binlog 文件中解析出这段范围内的事务内容，里面有我们需要的时间：

注意看里面的 TIMESTAMP 内容，意思是事务开始时的时间是21:45:38:572，原始内容精确到了微秒级别，我们这里只取毫秒来计算。

然后拿事务开始的 position 去 dm-worker 的日志中搜索相应的内容，当 binlog 被处理完成后会输出flushed checkpoint字样的内容，我们根据关键字去日志文件中搜索：

从这里可以得到 1422 被写入完成的时间是21:45:38.603，前后相减一下大概时间差是 31ms。

要注意的是，我理解整个链路的过程应该是：mysql(事务开始)->binlog->dm-master->dm-worker->tidb->dm-worker，相当于 TiDB 写完后多了一个通知 dm-worker 的过程。

基于 TiDB General log

第二种与前一种类似，我希望能定位到事务实际被 TiDB 执行完成的时间，这时候可以借助 TiDB 的GENERAL_LOG功能，用事务号（TSO）去定位。

我们首先打开 TiDB 实例的 General Log 开关：

mysql> set tidb_general_log=1;Query OK, 0 rows affected (0.08 sec)

前半部分和之前一样，还是去 binlog 文件中找到 MySQL 事务开始时间戳，这里是22:08:55:419：

然后打开 TiBD 的 Dashboard 页面，用如下关键字搜索 TiDB 节点的日志：

虽然这个页面能看到日志的记录时间，但是存在两个问题，一个是不能精确到毫秒，第二个这并不是事务的提交时间，我们需要进一步根据事务号（TSO）去原始文件中搜索准确时间。

这里的 commit 时间是22:08:55.434，前后相减的时间差大概 15ms。

这里也可以一步到位直接去原始 log 文件去搜，省去 Dashboard 查询 TSO 的过程。

这个链路过程是：mysql(事务开始)->binlog->dm-master->dm-worker->tidb(事务提交)。

基于 SQL 自动记录时间

前面两种方法都要各种搜索日志稍微有点麻烦，本着将偷懒进行到底的精神，能不能直观地看出上下游各自的时间？最理想的情况是：一句 SQL 就能查出来。

从前面的测试中可以发现，时间字段设置当前时间为默认值只对上游生效，同步到 TiDB 的时候是把实际值传过去了，并不是根据字段定义生成新值。因此，我希望数据到 TiBD 的时候也能生成当前时间写入某个字段，但是这个字段不能在 MySQL 中存在，也就是说上下游数据结构不一样。

那 DM 可以支持这种同步吗？必然是可以的。

关于上下游异构同步官网文档有详细介绍，大家可以参考文档：https://docs.pingcap.com/zh/tidb-data-migration/stable/manage-schema。

我们要使用的带默认值异构同步其实更简单，DM 不用做任何操作就能支持。

我们在前面的 DM Task 完全不动的情况下，只给下游 TiDB 的 table1 增加一个字段：

alter table table1 add COLUMN tidb_created timestamp(3) NOT NULL  DEFAULT current_timestamp(3);

然后往上游插入一条测试数据：

insert into table1 values(3,null);

插入成功后去 TiDB 中查询这个表，两个创建时间都能看到了：

是不是非常简单。

这个链路的过程是：mysql(事务开始)->binlog->dm-master->dm-worker->tidb(事务开始)。

总结

以上 3 种方式从不同维度计算了一次数据同步的延时情况，这个数据具有一定的参考性。但是使用的过程中要注意每一种的区别，选择你最适合最关心的指标来作为参考。

本文如有不正确的地方欢迎指出，当然了，也欢迎大家推荐更好的方案，一起交流~