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

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

  • 【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]

稍等,我确认下,答复

请问DM版本是什么?

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

看了一下、我可以看到了,谢谢啊: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]

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"]

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

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

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

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

嗯,是的

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

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

dm同步有点长:sweat_smile:

mysql写到binlog时间
18:17:01.382

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

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

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

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

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

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

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

你好,

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

image

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

好的,谢谢。

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

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

1赞