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

谁践踏了优雅 2023-10-01 10:24 8阅读 0赞

### 背景 ###

用户在做技术选型的过程中，总是会对一些数据指标比较关心，特别是在和竞品相比较的时候，更加需要一些有说服力的数据。基于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：

![b37ca425b1132d6c6acad0a68c505006.png][]

![582f11aad8725d643efb5bd9b650a371.png][]

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

![051e5f295d0cd278fc9c3da217112be4.png][]

![6a4dcf40e4ceb3a96e3761228fb89f78.png][]

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

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

![79e9fc6c5d9d96ea340f5f2bbcd766e7.png][]

![e28128fb2a92f67bfd82f7ec40f3d009.png][]

从这里可以得到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`：

![8a9ea80f74f4e284121985bf31ca21d6.png][]

![1aaca55d1e60f103ac61e1cccbe8e977.png][]

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

![64d902d2e81a7e7603ca410923ac2d6a.png][]

![166119c830d2a4667371246dc3f37e7a.png][]

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

![cfc0389cdaff7a53ab05109e253c45bb.png][]

![2ba936871501bbbf98f4c8f153cad933.png][]

这里的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。][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中查询这个表，两个创建时间都能看到了：

![45815d50455218723e80f3efca7e0ed9.png][]

![4e0af0af1ccfbd09ddc5119c9c213cf8.png][]

是不是非常简单。

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

### 总结 ###

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

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

[b37ca425b1132d6c6acad0a68c505006.png]: https://img-blog.csdnimg.cn/img_convert/b37ca425b1132d6c6acad0a68c505006.png
[582f11aad8725d643efb5bd9b650a371.png]: https://img-blog.csdnimg.cn/img_convert/582f11aad8725d643efb5bd9b650a371.png
[051e5f295d0cd278fc9c3da217112be4.png]: https://img-blog.csdnimg.cn/img_convert/051e5f295d0cd278fc9c3da217112be4.png
[6a4dcf40e4ceb3a96e3761228fb89f78.png]: https://img-blog.csdnimg.cn/img_convert/6a4dcf40e4ceb3a96e3761228fb89f78.png
[79e9fc6c5d9d96ea340f5f2bbcd766e7.png]: https://img-blog.csdnimg.cn/img_convert/79e9fc6c5d9d96ea340f5f2bbcd766e7.png
[e28128fb2a92f67bfd82f7ec40f3d009.png]: https://img-blog.csdnimg.cn/img_convert/e28128fb2a92f67bfd82f7ec40f3d009.png
[8a9ea80f74f4e284121985bf31ca21d6.png]: https://img-blog.csdnimg.cn/img_convert/8a9ea80f74f4e284121985bf31ca21d6.png
[1aaca55d1e60f103ac61e1cccbe8e977.png]: https://img-blog.csdnimg.cn/img_convert/1aaca55d1e60f103ac61e1cccbe8e977.png
[64d902d2e81a7e7603ca410923ac2d6a.png]: https://img-blog.csdnimg.cn/img_convert/64d902d2e81a7e7603ca410923ac2d6a.png
[166119c830d2a4667371246dc3f37e7a.png]: https://img-blog.csdnimg.cn/img_convert/166119c830d2a4667371246dc3f37e7a.png
[cfc0389cdaff7a53ab05109e253c45bb.png]: https://img-blog.csdnimg.cn/img_convert/cfc0389cdaff7a53ab05109e253c45bb.png
[2ba936871501bbbf98f4c8f153cad933.png]: https://img-blog.csdnimg.cn/img_convert/2ba936871501bbbf98f4c8f153cad933.png
[https_docs.pingcap.com_zh_tidb-data-migration_stable_manage-schema]: https://link.zhihu.com/?target=https%3A//docs.pingcap.com/zh/tidb-data-migration/stable/manage-schema%25E3%2580%2582
[45815d50455218723e80f3efca7e0ed9.png]: https://img-blog.csdnimg.cn/img_convert/45815d50455218723e80f3efca7e0ed9.png
[4e0af0af1ccfbd09ddc5119c9c213cf8.png]: https://img-blog.csdnimg.cn/img_convert/4e0af0af1ccfbd09ddc5119c9c213cf8.png