drainer启动了但是没有新数据

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

  • 【TiDB 版本】:5.7.25-TiDB-v4.0.0-alpha-804-g94d728bf4
  • 【问题描述】: drainer已经启动了,但是mysql上一直没有新数据

配置如下:

drainer_mysql1 ansible_host=172.16.112.198 ansible_ssh_port=17156 initial_commit_ts=“418362053361139715”
drainer_mysql2 ansible_host=172.16.112.202 ansible_ssh_port=17156 initial_commit_ts=“418362053361139715”
drainer_mysql3 ansible_host=172.16.112.200 ansible_ssh_port=17156 initial_commit_ts=“418362053361139715”

[2020/07/29 15:05:24.618 +08:00] [INFO] [nodes.go:52] [“query node”] [type=drainer] [node="{NodeID: database-tikv-1.hzh.yidui.vip:8249, Addr: 172.16.112.198:8249, State: online, MaxCommitTS: 418383480959270913, UpdateTime: 2020-07-29 15:05:23 +0800 CST}"]
[2020/07/29 15:05:24.618 +08:00] [INFO] [nodes.go:52] [“query node”] [type=drainer] [node="{NodeID: database-tikv-2.hzh.yidui.vip:8249, Addr: 172.16.112.202:8249, State: online, MaxCommitTS: 418383480959270913, UpdateTime: 2020-07-29 15:05:23 +0800 CST}"]
[2020/07/29 15:05:24.618 +08:00] [INFO] [nodes.go:52] [“query node”] [type=drainer] [node="{NodeID: database-tikv-3.hzh.yidui.vip:8249, Addr: 172.16.112.200:8249, State: online, MaxCommitTS: 418383481549094920, UpdateTime: 2020-07-29 15:05:23 +0800 CST}"]

若提问为性能优化、故障排查类问题,请下载脚本运行。终端输出的打印结果,请务必全选并复制粘贴上传。

日志情况:

[2020/07/29 15:33:21.307 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418383920915546113]
[2020/07/29 15:33:25.138 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418383921701978122]
[2020/07/29 15:33:28.230 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418383923065126913]
[2020/07/29 15:33:33.320 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418383924061274113]
[2020/07/29 15:33:37.150 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418383924847706114]
[2020/07/29 15:33:40.243 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418383926210854915]

有个问题 就是data.drainer里面是空的

看下 drainer 的配置文件是否有对库表进行过滤呢。可以提供看下。
tidb-binlog 是 tidb 的增量复制工具,看下上游执行的事务中在下游是否存在对应的 schema 和 table 和 data

ignore-schemas = “INFORMATION_SCHEMA,PERFORMANCE_SCHEMA,mysql”

1# replicate-do-db priority over replicate-do-table if have same db name
1# and we support regex expression , start with ‘~’ declare use regex expression.
1# replicate-do-db = ["~^b.*",“s1”]
1# [[syncer.replicate-do-table]]
1# db-name =“test”
1# tbl-name = “log”

1# [[syncer.replicate-do-table]]
1# db-name =“test”
1# tbl-name = “~^a.*”

1# disable sync these table
1# [[syncer.ignore-table]]
1# db-name = “test”
1# tbl-name = “log”

这部分都是默认的 没有改

请提供下完整 drainer log 和 配置文件,辛苦,另外上面的问题是否已经确认了呢

[2020/07/29 15:47:31.457 +08:00] [INFO] [version.go:50] [“Welcome to Drainer”] [“Release Version”=v3.0.4-17-g041c049-dirty] [“Git Commit Hash”=041c049331c370fdebd1e87a1dd9e9af0252bcd0] [“Build TS”=“2019-11-05 02:39:26”] [“Go Version”=go1.12] [“Go OS/Arch”=linux/amd64]
[2020/07/29 15:47:31.457 +08:00] [INFO] [main.go:46] [“start drainer…”] [config="{“log-level”:“info”,“node-id”:"",“addr”:“http://172.16.112.198:8249”,“advertise-addr”:“http://172.16.112.198:8249”,“data-dir”:"/mnt/deploy/data.drainer",“detect-interval”:10,“pd-urls”:“http://172.16.112.198:2379,http://172.16.112.202:2379,http://172.16.112.200:2379”,“log-file”:"/mnt/deploy/log/drainer.log",“initial-commit-ts”:418362053361139715,“sycner”:{“sql-mode”:null,“ignore-txn-commit-ts”:[],“ignore-schemas”:“INFORMATION_SCHEMA,PERFORMANCE_SCHEMA,mysql”,“ignore-table”:null,“txn-batch”:20,“worker-count”:16,“to”:{“host”:"",“user”:"",“password”:"",“port”:3306,“checkpoint”:{“type”:"",“schema”:"",“host”:"",“user”:"",“password”:"",“port”:0},“dir”:"",“time-limit”:"",“size-limit”:"",“zookeeper-addrs”:"",“kafka-addrs”:"",“kafka-version”:"",“kafka-max-messages”:0,“topic-name”:""},“replicate-do-table”:null,“replicate-do-db”:null,“db-type”:“mysql”,“enable-dispatch”:true,“safe-mode”:false,“enable-detect”:false},“security”:{“ssl-ca”:"",“ssl-cert”:"",“ssl-key”:""},“synced-check-time”:5,“compressor”:"",“EtcdTimeout”:5000000000,“MetricsAddr”:"",“MetricsInterval”:15}"]
[2020/07/29 15:47:31.457 +08:00] [INFO] [client.go:144] ["[pd] create pd client with endpoints"] [pd-address="[http://172.16.112.198:2379,http://172.16.112.200:2379,http://172.16.112.202:2379]"]
[2020/07/29 15:47:31.460 +08:00] [INFO] [client.go:252] ["[pd] switch leader"] [new-leader=http://172.16.112.198:2379] [old-leader=]
[2020/07/29 15:47:31.460 +08:00] [INFO] [client.go:163] ["[pd] init cluster id"] [cluster-id=6757968313974226271]
[2020/07/29 15:47:31.460 +08:00] [INFO] [server.go:111] [“get cluster id from pd”] [id=6757968313974226271]
[2020/07/29 15:47:31.477 +08:00] [INFO] [checkpoint.go:63] [“initialize checkpoint”] [type=mysql] [checkpoint=418384123906752515] [cfg="{“CheckpointType”:“mysql”,“Db”:{“host”:"",“user”:"","":"",“port”:3306},“Schema”:“tidb_binlog”,“Table”:“checkpoint”,“ClusterID”:6757968313974226271,“InitialCommitTS”:418362053361139715,“dir”:"/mnt/deploy/data.drainer/savepoint"}"]
[2020/07/29 15:47:31.477 +08:00] [INFO] [store.go:68] [“new store”] [path=“tikv://172.16.112.198:2379,172.16.112.200:2379,172.16.112.202:2379?disableGC=true”]
[2020/07/29 15:47:31.477 +08:00] [INFO] [client.go:144] ["[pd] create pd client with endpoints"] [pd-address="[172.16.112.198:2379,172.16.112.200:2379,172.16.112.202:2379]"]
[2020/07/29 15:47:31.479 +08:00] [INFO] [client.go:252] ["[pd] switch leader"] [new-leader=http://172.16.112.198:2379] [old-leader=]
[2020/07/29 15:47:31.479 +08:00] [INFO] [client.go:163] ["[pd] init cluster id"] [cluster-id=6757968313974226271]
[2020/07/29 15:47:31.479 +08:00] [INFO] [store.go:74] [“new store with retry success”]
[2020/07/29 15:47:34.668 +08:00] [INFO] [store.go:68] [“new store”] [path=“tikv://172.16.112.198:2379,172.16.112.200:2379,172.16.112.202:2379?disableGC=true”]
[2020/07/29 15:47:34.668 +08:00] [INFO] [client.go:144] ["[pd] create pd client with endpoints"] [pd-address="[172.16.112.198:2379,172.16.112.200:2379,172.16.112.202:2379]"]
[2020/07/29 15:47:34.669 +08:00] [INFO] [client.go:252] ["[pd] switch leader"] [new-leader=http://172.16.112.198:2379] [old-leader=]
[2020/07/29 15:47:34.669 +08:00] [INFO] [client.go:163] ["[pd] init cluster id"] [cluster-id=6757968313974226271]
[2020/07/29 15:47:34.670 +08:00] [INFO] [store.go:74] [“new store with retry success”]
[2020/07/29 15:47:34.673 +08:00] [INFO] [server.go:255] [“register success”] [“drainer node id”=database-tikv-1.hzh.yidui.vip:8249]
[2020/07/29 15:47:34.673 +08:00] [INFO] [server.go:308] [“start to server request”] [addr=http://172.16.112.198:8249]
[2020/07/29 15:47:34.673 +08:00] [INFO] [merge.go:222] [“merger add source”] [“source id”=database-tikv-1.hzh.yidui.vip:8250]
[2020/07/29 15:47:34.673 +08:00] [INFO] [merge.go:222] [“merger add source”] [“source id”=database-tikv-2.hzh.yidui.vip:8250]
[2020/07/29 15:47:34.673 +08:00] [INFO] [merge.go:222] [“merger add source”] [“source id”=database-tikv-3.hzh.yidui.vip:8250]
[2020/07/29 15:47:34.673 +08:00] [INFO] [pump.go:133] [“pump create pull binlogs client”] [id=database-tikv-3.hzh.yidui.vip:8250]
[2020/07/29 15:47:34.673 +08:00] [INFO] [pump.go:133] [“pump create pull binlogs client”] [id=database-tikv-2.hzh.yidui.vip:8250]
[2020/07/29 15:47:34.673 +08:00] [INFO] [pump.go:133] [“pump create pull binlogs client”] [id=database-tikv-1.hzh.yidui.vip:8250]
[2020/07/29 15:47:37.678 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418384145730240517]
[2020/07/29 15:47:42.783 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418384146713280527]
[2020/07/29 15:47:46.493 +08:00] [INFO] [syncer.go:251] [“write save point”] [ts=418384147525926917]

请问 initial_commit_ts 是从哪里得到的呢。
pump log 辛苦也发一下

initial_commit_ts 是mydumper里的信息。
pump log:
[2020/07/29 16:21:20.857 +08:00] [INFO] [storage.go:384] [DBStats] [DBStats="{“WriteDelayCount”:0,“WriteDelayDuration”:0,“WritePaused”:false,“AliveSnapshots”:0,“AliveIterators”:0,“IOWrite”:24524162,“IORead”:0,“BlockCacheSize”:0,“OpenedTablesCount”:0,“LevelSizes”:null,“LevelTablesCounts”:null,“LevelRead”:null,“LevelWrite”:null,“LevelDurations”:null}"]
[2020/07/29 16:21:20.859 +08:00] [INFO] [server.go:548] [“server info tick”] [writeBinlogCount=0] [alivePullerCount=3] [MaxCommitTS=418384676152410115]
[2020/07/29 16:21:30.861 +08:00] [INFO] [storage.go:384] [DBStats] [DBStats="{“WriteDelayCount”:0,“WriteDelayDuration”:0,“WritePaused”:false,“AliveSnapshots”:0,“AliveIterators”:0,“IOWrite”:24524739,“IORead”:0,“BlockCacheSize”:0,“OpenedTablesCount”:0,“LevelSizes”:null,“LevelTablesCounts”:null,“LevelRead”:null,“LevelWrite”:null,“LevelDurations”:null}"]
[2020/07/29 16:21:30.866 +08:00] [INFO] [server.go:548] [“server info tick”] [writeBinlogCount=0] [alivePullerCount=3] [MaxCommitTS=418384678511706115]
[2020/07/29 16:21:40.857 +08:00] [INFO] [storage.go:384] [DBStats] [DBStats="{“WriteDelayCount”:0,“WriteDelayDuration”:0,“WritePaused”:false,“AliveSnapshots”:0,“AliveIterators”:0,“IOWrite”:24525231,“IORead”:0,“BlockCacheSize”:0,“OpenedTablesCount”:0,“LevelSizes”:null,“LevelTablesCounts”:null,“LevelRead”:null,“LevelWrite”:null,“LevelDurations”:null}"]
[2020/07/29 16:21:40.859 +08:00] [INFO] [server.go:548] [“server info tick”] [writeBinlogCount=0] [alivePullerCount=3] [MaxCommitTS=418384680871002122]
[2020/07/29 16:21:50.857 +08:00] [INFO] [storage.go:384] [DBStats] [DBStats="{“WriteDelayCount”:0,“WriteDelayDuration”:0,“WritePaused”:false,“AliveSnapshots”:0,“AliveIterators”:0,“IOWrite”:24525802,“IORead”:0,“BlockCacheSize”:0,“OpenedTablesCount”:0,“LevelSizes”:null,“LevelTablesCounts”:null,“LevelRead”:null,“LevelWrite”:null,“LevelDurations”:null}"]
[2020/07/29 16:21:50.862 +08:00] [INFO] [server.go:548] [“server info tick”] [writeBinlogCount=0] [alivePullerCount=3] [MaxCommitTS=418384684016730115]
[2020/07/29 16:22:00.857 +08:00] [INFO] [storage.go:384] [DBStats] [DBStats="{“WriteDelayCount”:0,“WriteDelayDuration”:0,“WritePaused”:false,“AliveSnapshots”:0,“AliveIterators”:0,“IOWrite”:24526379,“IORead”:0,“BlockCacheSize”:0,“OpenedTablesCount”:0,“LevelSizes”:null,“LevelTablesCounts”:null,“LevelRead”:null,“LevelWrite”:null,“LevelDurations”:null}"]
[2020/07/29 16:22:00.859 +08:00] [INFO] [server.go:548] [“server info tick”] [writeBinlogCount=0] [alivePullerCount=3] [MaxCommitTS=418384686389133313]

pump 貌似也不是完整的信息吧,辛苦提供下完成的 welcome 的信息。上传附件也是可以的。

123.rar (779.7 KB)

压缩了一下 源文件23MB 我担心传上来慢

辛苦帮忙按照以下方式帮忙排查下问题:

  1. 在上游执行 create database asktug_test;create table tbl(id int);insert into asktug_test.tbl values(1),(2);

看下下游 tidb 中的情况

我是从tidb-binlog到mysql

tidb算是上游?
mysql是下游?

sorry,更正下
辛苦帮忙按照以下方式帮忙排查下问题:

  1. 在上游 tidb 执行 create database asktug_test;create table tbl(id int);insert into asktug_test.tbl values(1),(2);

看下下游 mysql 中的情况,

下游mysql没有反应,并没有创建db。

我感觉是pump没有数据,
怎么验证pump是成功有数据的?

看下监控中是否是 binlog 延迟呢。

看下
95% Binlog Reach Duration By Pump
SQL Query Time
Queue Size

就是drainer的grafana没有数据,是不是哪里有问题?