dm过程执行sql的开始时间、执行sql、结束时间

zhengyunpeng · 2020 年4 月 18 日 06:27

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

【TiDB 版本】：4.0
【问题描述】：
mysql到tidb的同步的延迟只要不是在日志的同步，而是在tidb执行sql的时间。这个好像没法对比上游一个事务在tidb上最终执行完的时间差

目前我们的日志本身同步时纳秒级的，但是页面数据删除后立即查询还有出现数据不一致，查询到了删除的数据

通过设置general log = 1然后查看tidb.log的日志发现：
1.业务查询、直接通过jdbc连接数据库查询，tidb.log中能看到查询的sql
2.dm同步的数据没有执行的sql
3.dm同步会打印dm同步数据库dm_meta的数据

我想要的日志：dm同步数据执行的sql，即上游MySQL数据库更改数据的sql
例：
我在mysql数据库执行insert into test.test values(1,‘aa’) 目前在下游数据库我只能看到dm_meta.test_tidb_syncer_checkpoint的操作日志，看不到test.test的insert into的日志

[2020/04/18 14:25:35.797 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 14:25:35.798 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416072633096863747] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `dm_meta`.`test_tidb_syncer_checkpoint` (`id`, `cp_schema`, `cp_table`, `binlog_name`, `binlog_pos`, `is_global`) VALUES('mysql4','','','db1m-bin|000001.000047',64589193,1) ON DUPLICATE KEY UPDATE `binlog_name`='db1m-bin|000001.000047', `binlog_pos`=64589193"]
[2020/04/18 14:25:35.802 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416072633096863747] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 14:26:07.404 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 14:26:07.405 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416072641380614145] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `dm_meta`.`test_tidb_syncer_checkpoint` (`id`, `cp_schema`, `cp_table`, `binlog_name`, `binlog_pos`, `is_global`) VALUES('mysql4','','','db1m-bin|000001.000047',64596515,1) ON DUPLICATE KEY UPDATE `binlog_name`='db1m-bin|000001.000047', `binlog_pos`=64596515"]
[2020/04/18 14:26:07.410 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416072641380614145] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 14:26:38.911 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 14:26:38.912 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416072649638150148] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `dm_meta`.`test_tidb_syncer_checkpoint` (`id`, `cp_schema`, `cp_table`, `binlog_name`, `binlog_pos`, `is_global`) VALUES('mysql4','','','db1m-bin|000001.000047',64606523,1) ON DUPLICATE KEY UPDATE `binlog_name`='db1m-bin|000001.000047', `binlog_pos`=64606523"]
[2020/04/18 14:26:38.916 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416072649638150148] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]

yilong · 2020 年4 月 18 日 06:37

稍等，我确认下，答复

yilong · 2020 年4 月 18 日 07:15

请问DM版本是什么？

应该是一致的，也会记录
请看下您配置的task是否有过滤这条信息
或者查看下游是否有这个记录写入，多谢。
请上传dm-worker的日志，多谢

zhengyunpeng · 2020 年4 月 18 日 07:21

看了一下、我可以看到了，谢谢啊:sweat_smile:

为什么插入一条语句就要毫秒级

配置：

[2020/04/18 15:14:36.189 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 15:14:36.190 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073403905081345] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `dm_meta`.`test_tidb_syncer_checkpoint` (`id`, `cp_schema`, `cp_table`, `binlog_name`, `binlog_pos`, `is_global`) VALUES('mysql4','','','db1m-bin|000001.000047',65470827,1) ON DUPLICATE KEY UPDATE `binlog_name`='db1m-bin|000001.000047', `binlog_pos`=65470827"]
[2020/04/18 15:14:36.195 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073403905081345] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 15:14:48.296 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1893] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 15:14:48.296 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 15:14:48.297 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1893] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023745] [current_db=] [txn_mode=PESSIMISTIC] [sql="UPDATE `h3_stock`.`t_stock_a` SET `id` = 758817, `group_id` = 20000, `company_id` = 100120178, `business_id` = 100120184, `ware_inside_code` = 10088, `qualified_qty` = 10, `reserved_qty` = 0, `to_be_inspected_qty` = 0, `unqualified_qty` = 0, `in_transit_qty` = 0, `expected_qty` = 1005, `to_be_processed_qty` = 0, `weighted_average_price` = 0, `modify_time` = '2020-04-18 15:13:40.891' WHERE `id` = 758817 LIMIT 1;"]
[2020/04/18 15:14:48.297 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023746] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `h3_warehouse`.`t_warehouse_initial_stock` (`id`,`initial_stock_code`,`group_id`,`company_id`,`business_id`,`supplier_code`,`supplier_inside_code`,`user_id`,`settler_code`,`payment_period`,`pay_type`,`target_business_id`,`document_status`,`after_status`,`effect_time`,`create_user`,`create_time`,`modify_user`,`modify_time`,`instance_id`,`note`,`is_delete`) VALUES (68,'QCRK20200418000003',20000,100120178,100120184,'820056',820056,6666,'0002',28,16,NULL,2,NULL,NULL,6666,'2020-04-18 15:13:41',6666,'2020-04-18 15:13:41','1208312','',2);"]
[2020/04/18 15:14:48.301 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1893] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023745] [current_db=] [txn_mode=PESSIMISTIC] [sql="UPDATE `h3_stock`.`t_stock_a` SET `id` = 758816, `group_id` = 20000, `company_id` = 100120178, `business_id` = 100120184, `ware_inside_code` = 10019, `qualified_qty` = 6, `reserved_qty` = 0, `to_be_inspected_qty` = 0, `unqualified_qty` = 0, `in_transit_qty` = 0, `expected_qty` = 1277, `to_be_processed_qty` = 3, `weighted_average_price` = 0, `modify_time` = '2020-04-18 15:13:40.891' WHERE `id` = 758816 LIMIT 1;"]
[2020/04/18 15:14:48.302 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023746] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `h3_warehouse`.`t_warehouse_initial_stock_ware` (`id`,`initial_stock_id`,`ware_code`,`ware_inside_code`,`made_number`,`stall_id`,`ware_number`,`purchase_price`,`production_date`,`valid_until`,`sterilization_batch_number`,`sterilization_time`,`purchase_tax_rate_id`,`sale_tax_rate_id`,`is_delete`) VALUES (130,68,'10088',10088,'PH20200417',3571,1000,10,'2020-04-01','2024-05-04','MJ123456789',NULL,8,7,2);"]
[2020/04/18 15:14:48.304 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1893] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023745] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 15:14:48.306 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023746] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `h3_warehouse`.`t_warehouse_initial_stock_ware` (`id`,`initial_stock_id`,`ware_code`,`ware_inside_code`,`made_number`,`stall_id`,`ware_number`,`purchase_price`,`production_date`,`valid_until`,`sterilization_batch_number`,`sterilization_time`,`purchase_tax_rate_id`,`sale_tax_rate_id`,`is_delete`) VALUES (131,68,'10019',10019,'PH20200418',3572,1200,30,'2020-04-01','2025-04-26','MJ789456123',NULL,6,6,2);"]
[2020/04/18 15:14:48.309 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023746] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `h3_stock`.`t_stock_idempotence` (`id`,`group_id`,`company_id`,`business_id`,`bill_type`,`bill_number`,`business_type`,`operate_time__millis_str`) VALUES (3295,20000,100120178,100120184,19,'QCRK20200418000003',1,'1587194020859');"]
[2020/04/18 15:14:48.312 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073407077023746] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 15:15:02.502 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 15:15:02.503 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073410799468546] [current_db=] [txn_mode=PESSIMISTIC] [sql="UPDATE `h3_stock`.`t_stock_a` SET `id` = 758732, `group_id` = 20000, `company_id` = 100120178, `business_id` = 100120184, `ware_inside_code` = 10008, `qualified_qty` = -17, `reserved_qty` = 25, `to_be_inspected_qty` = 0, `unqualified_qty` = 0, `in_transit_qty` = 0, `expected_qty` = 88, `to_be_processed_qty` = 0, `weighted_average_price` = 0, `modify_time` = '2020-04-18 15:13:55.133' WHERE `id` = 758732 LIMIT 1;"]
[2020/04/18 15:15:02.507 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1895] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073410799468546] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]

zhengyunpeng · 2020 年4 月 18 日 07:32

dm收集sql发送到tidb执行有没有批处理？
事务之间经常会有秒级的时间差，是因为dm同步做了处理吗？

[2020/04/18 15:29:47.137 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1897] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073642705158146] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 15:29:47.137 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=1896] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073642705158147] [current_db=] [txn_mode=PESSIMISTIC] [sql=COMMIT]
[2020/04/18 15:30:02.332 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=0] [current_db=] [txn_mode=PESSIMISTIC] [sql="START TRANSACTION"]
[2020/04/18 15:30:02.333 +08:00] [INFO] [session.go:2139] [GENERAL_LOG] [conn=7] [user=root@192.168.10.101] [schemaVersion=660] [txnStartTS=416073646689746945] [current_db=] [txn_mode=PESSIMISTIC] [sql="INSERT INTO `dm_meta`.`test_tidb_syncer_checkpoint` (`id`, `cp_schema`, `cp_table`, `binlog_name`, `binlog_pos`, `is_global`) VALUES('mysql4','','','db1m-bin|000001.000047',65906597,1) ON DUPLICATE KEY UPDATE `binlog_name`='db1m-bin|000001.000047', `binlog_pos`=65906597"]

yilong · 2020 年4 月 18 日 08:32

tidb提交是两阶段提交，可以根据您使用乐观锁还是悲观锁查一文档 https://pingcap.com/docs-cn/dev/reference/transactions/transaction-pessimistic/
批处理是指什么？ dm是根据拉取的relay log来同步数据的

zhengyunpeng · 2020 年4 月 18 日 08:34

好的，我在看一下锁的问题

拉取的relay log的时候是多久拉取一次？

yilong · 2020 年4 月 18 日 08:36

会不断拉取，你的意思就是要两个事务之间在tidb毫秒级以下？

zhengyunpeng · 2020 年4 月 18 日 10:37

嗯，是的

yilong · 2020 年4 月 18 日 12:35

这个感觉不一定能保证，你的两个事务，不一定在一个binlog文件里，dm读取文件再去同步，有可能超过这个时间

zhengyunpeng · 2020 年4 月 19 日 09:22

不太理解你的意思
不在同一个binlog文件下是什么意思？
dm读取文件发送给tidb在同步看dm的web监控是纳秒级的
但是看general log日志会有很高的延迟，事务之间间隔可能达到秒级延迟

zhengyunpeng · 2020 年4 月 19 日 10:52

dm同步有点长

mysql写到binlog时间
18:17:01.382

tidb事务开始时间
18:17:02.332
tidb开始执行该语句时间
18:17:02.358
tidb事务结束时间
18:17:02.355

yilong · 2020 年4 月 20 日 02:04

mysql写到binlog之后，DM拉取到relaylog，然后读取relay log，将数据同步到tidb。这个流程感觉没办法达到你毫秒级的要求。

zhengyunpeng · 2020 年4 月 20 日 02:16

监控页面的这个cost of binlog event transform指标（Syncer 解析并且转换 binlog 成 SQLs 的耗时，单位：秒)才是微妙级的

zhengyunpeng · 2020 年4 月 20 日 02:19

1.dm拉取binlog是由mysql发送到dm还是dm去拉取？如果是dm拉取，拉取的机制是什么？
2.怎么查看binlog在dm总的链路信息？什么时候获取到、什么时候解析、什么时候生成relay log、什么时候发送到tidb。

yilong · 2020 年4 月 20 日 04:24

DM 从上游读 binlog，主要看 DM-worker 到 MySQL 的网络延迟； DM 内部较繁忙（但不是太繁忙）时，大致在 100us 左右；但比较空闲时，可能需要等待攒 batch，延迟可能需要到 10ms（如果比较空闲，又想降低延迟，可以调小 batch）； DM 向下游执行，需要考虑 DM-worker 到 TiDB 的网络延迟、TiDB 执行耗时等，这里一般快也要几十 ms 吧（这里网络延迟在大 batch 时表现会很明显）

zhengyunpeng · 2020 年4 月 20 日 04:32

好的，非常感谢。还有两个疑问

1.如何调小batch --》启动任务配置文件yaml 的syner配置里
2.mysql相关的问题。master启动线程向slave写日志。写的时机是事务执行完binlog刷盘前，还是binlog刷盘之后

来了老弟 · 2020 年4 月 20 日 04:47

你好，

增量同步可以通过 task - syncers - batch 修改 batch 数

这个根据 mysql 参数有关，原则上是 event 已经写入 binlog ，salve 才开始同步~

zhengyunpeng · 2020 年4 月 20 日 04:48

好的，谢谢。

怎么查看binlog在dm总的链路信息？什么时候获取到、什么时候解析、什么时候生成relay log、什么时候发送到tidb。

yilong · 2020 年4 月 20 日 06:09

查看relay log生成时间， dm-worker日志查找记录， tidb 开启 general log 查看.