DM v6.1全量导入停止后,再启动显示进度从零开始,没有断点续传

【环境】
TiDB v6.1.0
DM v6.1.0

【问题】
执行stop-task前:


执行stop-task,再执行start-task,等待N分钟后,执行query-status

任务配置:

相关日志:

[2022/06/30 09:22:48.714 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload=“name:"dm-mysql_report" “]
[2022/06/30 09:22:48.714 +08:00] [INFO] [source_worker.go:785] [“receive subtask stage change”] [stage=”{"expect":0,"source":"ds-mysql_report","task":"dm-mysql_report"}”] [“is deleted”=true]
[2022/06/30 09:22:48.714 +08:00] [INFO] [source_worker.go:815] [operateSubTaskStage] [sourceID=] [task=] [stage=“{"expect":0,"source":"ds-mysql_report","task":"dm-mysql_report"}”]
[2022/06/30 09:22:48.739 +08:00] [INFO] [source_worker.go:630] [“OperateSubTask start”] [component=“worker controller”] [op=Delete] [task=dm-mysql_report]
[2022/06/30 09:22:48.739 +08:00] [INFO] [source_worker.go:634] [“delete subtask”] [component=“worker controller”] [task=dm-mysql_report]
[2022/06/30 09:22:48.739 +08:00] [INFO] [subtask.go:560] [closing] [subtask=dm-mysql_report]
[2022/06/30 09:22:49.740 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload=“name:"dm-mysql_report" “]
[2022/06/30 09:22:52.309 +08:00] [ERROR] [lightning.go:274] [“failed to runlightning”] [task=dm-mysql_report] [unit=lightning-load] [error=“context canceled”] [errorVerbose=“context canceled
github.com/pingcap/errors.AddStack
\tgithub.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/errors.go:174
github.com/pingcap/errors.Trace
\tgithub.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/juju_adaptor.go:15
github.com/pingcap/tidb/br/pkg/lightning/restore.(*Controller).Run
\tgithub.com/pingcap/tidb@v1.1.0-beta.0.20220528045048-5495dc6c4360/br/pkg/lightning/restore/restore.go:446
github.com/pingcap/tidb/br/pkg/lightning.(*Lightning).run
\tgithub.com/pingcap/tidb@v1.1.0-beta.0.20220528045048-5495dc6c4360/br/pkg/lightning/lightning.go:464
github.com/pingcap/tidb/br/pkg/lightning.(*Lightning).RunOnceWithOptions
\tgithub.com/pingcap/tidb@v1.1.0-beta.0.20220528045048-5495dc6c4360/br/pkg/lightning/lightning.go:320
github.com/pingcap/tiflow/dm/loader.(*LightningLoader).runLightning
\tgithub.com/pingcap/tiflow/dm/loader/lightning.go:210
github.com/pingcap/tiflow/dm/loader.(*LightningLoader).restore
\tgithub.com/pingcap/tiflow/dm/loader/lightning.go:269
github.com/pingcap/tiflow/dm/loader.(*LightningLoader).Process
\tgithub.com/pingcap/tiflow/dm/loader/lightning.go:319
runtime.goexit
\truntime/asm_amd64.s:1571”]
[2022/06/30 09:22:52.309 +08:00] [INFO] [lightning.go:330] [“lightning load end”] [task=dm-mysql_report] [unit=lightning-load] [IsCanceled=true] [finished_bytes=693134497526] [total_bytes=2607018876675] [progress=“26.59 %”]
[2022/06/30 09:22:52.309 +08:00] [INFO] [subtask.go:356] [“unit process returned”] [subtask=dm-mysql_report] [unit=Load] [stage=Stopped] [status=”{"finishedBytes":693134497526,"totalBytes":2607018876675,"progress":"26.59 %","metaBinlog":"(mysql-bin.023389, 500217929)","metaBinlogGTID":"253894fc-4e58-11ec-9327-00163e014a6f:1-810968736,34474b1e-2bf3-11e8-8515-00163e1040fb:1-1278385,767d5889-e08e-11ea-bf83-00163e0e3732:1,7fbb40a3-8240-11eb-8cda-00163e17fb0e:1-754497392,803ffea1-7b9d-11e9-87b0-00163e0e3732:1-435424493,81db7142-4e58-11ec-b568-00163e19cf81:1,a2d27a7f-de3c-11e7-82cd-00163e1040fb:1-304056,a33473fb-de3c-11e7-8140-00163e0e6470:1-68232043,bfbebe4d-1582-11e9-8e63-00163e082a23:1-36011466,e033b7c4-7b9d-11e9-8e45-00163e097eeb:1-608218207"}”]
[2022/06/30 09:22:52.309 +08:00] [INFO] [subtask.go:428] [“closing unit process”] [subtask=dm-mysql_report] [unit=Load]
[2022/06/30 09:22:52.310 +08:00] [INFO] [subtask.go:430] [“closing unit done”] [subtask=dm-mysql_report] [unit=Load]
[2022/06/30 09:22:52.310 +08:00] [INFO] [subtask.go:428] [“closing unit process”] [subtask=dm-mysql_report] [unit=Load]
[2022/06/30 09:22:52.313 +08:00] [ERROR] [db.go:54] [“fail to close baseDB”] [task=dm-mysql_report] [unit=“binlog replication”] [error=“bad connection”]
[2022/06/30 09:22:52.313 +08:00] [ERROR] [db.go:54] [“fail to close baseDB”] [task=dm-mysql_report] [unit=“binlog replication”] [error=“bad connection”]
[2022/06/30 09:22:52.313 +08:00] [INFO] [subtask.go:430] [“closing unit done”] [subtask=dm-mysql_report] [unit=Load]
[2022/06/30 09:22:52.313 +08:00] [INFO] [source_worker.go:658] [“OperateSubTask finished”] [component=“worker controller”] [op=Delete] [task=dm-mysql_report]
[2022/06/30 09:22:56.903 +08:00] [INFO] [source_worker.go:785] [“receive subtask stage change”] [stage=“{"expect":2,"source":"ds-mysql_report","task":"dm-mysql_report"}”] [“is deleted”=false]
[2022/06/30 09:22:56.903 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload=“name:"dm-mysql_report" “]
[2022/06/30 09:22:57.518 +08:00] [INFO] [source_worker.go:815] [operateSubTaskStage] [sourceID=ds-mysql_report] [task=dm-mysql_report] [stage=”{"expect":2,"source":"ds-mysql_report","task":"dm-mysql_report"}”]
[2022/06/30 09:22:57.518 +08:00] [INFO] [source_worker.go:825] [“start to create subtask in operateSubTaskStage”] [sourceID=ds-mysql_report] [task=dm-mysql_report]
[2022/06/30 09:22:57.519 +08:00] [INFO] [source_worker.go:583] [“subtask created”] [component=“worker controller”] [config=“{"is-sharding":false,"shard-mode":"","online-ddl":true,"shadow-table-rules":["^(.+)(?:new|gho)$"],"trash-table-rules":["^(.+)(?:ghc|del|old)$"],"online-ddl-scheme":"","case-sensitive":false,"collation_compatible":"strict","name":"dm-mysql_report","mode":"all","ignore-checking-items":["dump_privilege"],"source-id":"ds-mysql_report","server-id":429534971,"flavor":"mysql","meta-schema":"dm_meta","heartbeat-update-interval":1,"heartbeat-report-interval":10,"enable-heartbeat":false,"timezone":"","meta":{"BinLogName":"","BinLogPos":0,"BinLogGTID":"253894fc-4e58-11ec-9327-00163e014a6f:1-782863893,34474b1e-2bf3-11e8-8515-00163e1040fb:1-1278385,767d5889-e08e-11ea-bf83-00163e0e3732:1,7fbb40a3-8240-11eb-8cda-00163e17fb0e:1-754497392,803ffea1-7b9d-11e9-87b0-00163e0e3732:1-435424493,a2d27a7f-de3c-11e7-82cd-00163e1040fb:1-304056,a33473fb-de3c-11e7-8140-00163e0e6470:1-68232043,bfbebe4d-1582-11e9-8e63-00163e082a23:1-36011466,e033b7c4-7b9d-11e9-8e45-00163e097eeb:1-608218207"},"relay-dir":"relay-dir","use-relay":false,"from":{"host":"172.18.79.251","port":15381,"user":"dm_sync","max-allowed-packet":null,"session":null,"security":null},"to":{"host":"172.17.201.177","port":15381,"user":"dm_load","max-allowed-packet":null,"session":{"tidb_txn_mode":"optimistic"},"security":null},"route-rules":,"filter-rules":,"mapping-rule":,"expression-filter":,"black-white-list":null,"block-allow-list":{"do-tables":null,"do-dbs":["report_center"],"ignore-tables":null,"ignore-dbs":null},"mydumper-path":"./bin/mydumper","threads":1,"chunk-filesize":"64","statement-size":0,"rows":1000,"where":"","skip-tz-utc":true,"extra-args":"–consistency none","pool-size":64,"dir":"./dm-mysql_report.dm-mysql_report","import-mode":"sql","on-duplicate":"replace","meta-file":"","worker-count":64,"batch":100,"queue-size":1024,"checkpoint-flush-interval":30,"compact":false,"multiple-rows":false,"max-retry":0,"auto-fix-gtid":false,"enable-gtid":true,"disable-detect":false,"safe-mode":false,"enable-ansi-quotes":false,"ValidatorCfg":{"mode":"none","worker-count":4,"validate-interval":{"Duration":"10s"},"check-interval":{"Duration":"5s"},"row-error-delay":{"Duration":"30m0s"},"meta-flush-interval":{"Duration":"1m0s"},"batch-query-size":100},"log-level":"","log-file":"","log-format":"","log-rotate":"","pprof-addr":"","status-addr":"","config-file":"","clean-dump-file":false,"ansi-quotes":false,"experimental":{"async-checkpoint-flush":false}}”]
[2022/06/30 09:22:57.583 +08:00] [INFO] [dumpling.go:354] [“found upstream SQL mode”] [task=dm-mysql_report] [unit=dump] [“SQL mode”=]
[2022/06/30 09:22:57.583 +08:00] [INFO] [dumpling.go:69] [“create dumpling”] [task=dm-mysql_report] [unit=dump] [config=“{"s3":{"endpoint":"","region":"","storage-class":"","sse":"","sse-kms-key-id":"","acl":"","access-key":"","secret-access-key":"","provider":"","force-path-style":false,"use-accelerate-endpoint":false},"gcs":{"endpoint":"","storage-class":"","predefined-acl":"","credentials-file":""},"azblob":{"endpoint":"","account-name":"","account-key":"","access-tier":""},"AllowCleartextPasswords":false,"SortByPk":true,"NoViews":true,"NoSequences":true,"NoHeader":false,"NoSchemas":false,"NoData":false,"CompleteInsert":true,"TransactionalConsistency":true,"EscapeBackslash":true,"DumpEmptyDatabase":true,"PosAfterConnect":true,"CompressType":0,"Host":"172.18.79.251","Port":15381,"Threads":1,"User":"dm_sync","Security":{"CAPath":"","CertPath":"","KeyPath":""},"LogLevel":"","LogFile":"","LogFormat":"","OutputDirPath":"./dm-mysql_report.dm-mysql_report","StatusAddr":"","Snapshot":"","Consistency":"none","CsvNullValue":"\\N","SQL":"","CsvSeparator":"","CsvDelimiter":"","Databases":null,"Where":"","FileType":"","ServerInfo":{"ServerType":0,"ServerVersion":null,"HasTiKV":false},"Rows":1000,"ReadTimeout":0,"TiDBMemQuotaQuery":0,"FileSize":67108864,"StatementSize":1000000,"SessionParams":{"time_zone":"+08:00"},"Tables":null,"CollationCompatible":"strict"}”]
[2022/06/30 09:22:57.707 +08:00] [INFO] [util.go:141] [“use timezone”] [task=dm-mysql_report] [unit=“binlog replication”] [location=+08:00] [host=172.18.79.251] [port=15381]
[2022/06/30 09:22:57.742 +08:00] [INFO] [util.go:141] [“use timezone”] [task=dm-mysql_report] [unit=“binlog replication”] [location=+08:00] [host=172.17.201.177] [port=15381]
[2022/06/30 09:22:57.931 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload=“name:"dm-mysql_report" “]
[2022/06/30 09:22:59.050 +08:00] [INFO] [checkpoint.go:945] [“create checkpoint schema”] [task=dm-mysql_report] [unit=“binlog replication”] [component=“remote checkpoint”] [statement=“CREATE SCHEMA IF NOT EXISTS dm_meta”]
[2022/06/30 09:22:59.058 +08:00] [INFO] [checkpoint.go:969] [“create checkpoint table”] [task=dm-mysql_report] [unit=“binlog replication”] [component=“remote checkpoint”] [statements=”["CREATE TABLE IF NOT EXISTS dm_meta.dm-mysql_report_syncer_checkpoint (\
\t\t\tid VARCHAR(32) NOT NULL,\
\t\t\tcp_schema VARCHAR(128) NOT NULL,\
\t\t\tcp_table VARCHAR(128) NOT NULL,\
\t\t\tbinlog_name VARCHAR(128),\
\t\t\tbinlog_pos INT UNSIGNED,\
\t\t\tbinlog_gtid TEXT,\
\t\t\texit_safe_binlog_name VARCHAR(128) DEFAULT ‘’,\
\t\t\texit_safe_binlog_pos INT UNSIGNED DEFAULT 0,\
\t\t\texit_safe_binlog_gtid TEXT,\
\t\t\ttable_info JSON NOT NULL,\
\t\t\tis_global BOOLEAN,\
\t\t\tcreate_time timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,\
\t\t\tupdate_time timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,\
\t\t\tUNIQUE KEY uk_id_schema_table (id, cp_schema, cp_table)\
\t\t)"]”]
[2022/06/30 09:22:59.063 +08:00] [WARN] [position.go:335] [“both gtidSets are empty, will compare by position”] [location1="position: (, 4), gtid-set: "] [location2="position: (, 4), gtid-set: "]
[2022/06/30 09:22:59.089 +08:00] [INFO] [subtask.go:203] [“continue unit”] [subtask=dm-mysql_report] [unit=Load]
[2022/06/30 09:22:59.089 +08:00] [INFO] [subtask.go:256] [“start to run”] [subtask=dm-mysql_report] [unit=Load]
[2022/06/30 09:22:59.089 +08:00] [INFO] [lightning.go:294] [“lightning load start”] [task=dm-mysql_report] [unit=lightning-load]
[2022/06/30 09:22:59.090 +08:00] [INFO] [util.go:201] [“put load worker in etcd”] [task=dm-mysql_report] [source=ds-mysql_report] [worker=dm-172.20.61.209-9262]
[2022/06/30 09:22:59.128 +08:00] [INFO] [checkpoint.go:570] [“initial checkpoint record”] [component=“lightning checkpoint database list”] [task=dm-mysql_report] [source=ds-mysql_report]
[2022/06/30 09:23:02.044 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:02.471 +08:00] [INFO] [source_worker.go:181] [“we just updated the source status, skip once”] [component=“worker controller”] [“last update time”=2022/06/30 09:23:02.070 +08:00]
[2022/06/30 09:23:05.283 +08:00] [INFO] [checkpoint.go:590] [“update lightning loader status”] [component=“lightning checkpoint database list”] [task=dm-mysql_report] [source=ds-mysql_report] [status=running]
[2022/06/30 09:23:05.797 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:07.286 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:08.369 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:09.423 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:10.352 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:11.261 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:12.250 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:20.158 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:26.554 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:28.207 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:29.384 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:30.674 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:31.643 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:32.471 +08:00] [INFO] [source_worker.go:181] [“we just updated the source status, skip once”] [component=“worker controller”] [“last update time”=2022/06/30 09:23:31.667 +08:00]
[2022/06/30 09:23:32.712 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:23:33.769 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:24:40.320 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:25:38.452 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:25:41.544 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:27:02.621 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:27:04.968 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:27:06.112 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]
[2022/06/30 09:27:07.339 +08:00] [INFO] [server.go:742] [request=QueryStatus] [payload="name:"dm-mysql_report" "]

您可以把这个 DM worker 此时的 goroutine 上传一下吗,我们看一下问题

http://:/debug/pprof/goroutine?debug=2

goroutine.txt (125.0 KB)

感谢反馈。看上去 lightning 还在正常工作,只是没有正确显示进度信息。您可以去下游查看一下表的行数有没有回退

我们这边会调查一下进度信息的问题

下游有写入,只是不知道是从头开始导入,还是接着之前的导入;而且重新start-task后,到真正向下游写数据,需要等好久(7~8分钟)

可以看一下,DM worker 日志相同目录下有 stdout/stderr 文件,那里面有输出吗?帮忙上传一下

-rw-r–r-- 1 admin grpcaocao 0 2022-06-28 14:46:58 dm-worker_stderr.log
-rw-r–r-- 1 admin grpcaocao 4.9K 2022-06-30 11:17:53 dm-worker_stdout.log
[admin@tidb-cdc01 log]$ cat dm-worker_stdout.log
[2022/06/29 05:58:23.080 +08:00] [INFO] [info.go:49] [“Welcome to TiDB-Lightning”] [component=“ddl tracker”] [release-version=v6.0.0-master] [git-hash=None] [git-branch=None] [go-version=go1.18.2] [utc-build-time=None] [race-enabled=false]
±–±---------------------------------------------±------------±-------+
| # | CHECK ITEM | TYPE | PASSED |
±–±---------------------------------------------±------------±-------+
| 1 | Source csv files size is proper | performance | true |
±–±---------------------------------------------±------------±-------+
| 2 | checkpoints are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 3 | table schemas are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 4 | Cluster is available | critical | true |
±–±---------------------------------------------±------------±-------+
| 5 | Lightning has the correct storage permission | critical | true |
±–±---------------------------------------------±------------±-------+

[2022/06/30 09:23:05.295 +08:00] [INFO] [info.go:49] [“Welcome to TiDB-Lightning”] [component=“ddl tracker”] [release-version=v6.0.0-master] [git-hash=None] [git-branch=None] [go-version=go1.18.2] [utc-build-time=None] [race-enabled=false]
±–±---------------------------------------------±------------±-------+
| # | CHECK ITEM | TYPE | PASSED |
±–±---------------------------------------------±------------±-------+
| 1 | Source csv files size is proper | performance | true |
±–±---------------------------------------------±------------±-------+
| 2 | checkpoints are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 3 | table schemas are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 4 | Cluster is available | critical | true |
±–±---------------------------------------------±------------±-------+
| 5 | Lightning has the correct storage permission | critical | true |
±–±---------------------------------------------±------------±-------+

[2022/06/30 09:44:51.928 +08:00] [INFO] [info.go:49] [“Welcome to TiDB-Lightning”] [component=“ddl tracker”] [release-version=v6.0.0-master] [git-hash=None] [git-branch=None] [go-version=go1.18.2] [utc-build-time=None] [race-enabled=false]
±–±---------------------------------------------±------------±-------+
| # | CHECK ITEM | TYPE | PASSED |
±–±---------------------------------------------±------------±-------+
| 1 | Source csv files size is proper | performance | true |
±–±---------------------------------------------±------------±-------+
| 2 | checkpoints are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 3 | table schemas are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 4 | Cluster is available | critical | true |
±–±---------------------------------------------±------------±-------+
| 5 | Lightning has the correct storage permission | critical | true |
±–±---------------------------------------------±------------±-------+

[2022/06/30 11:15:20.809 +08:00] [INFO] [info.go:49] [“Welcome to TiDB-Lightning”] [component=“ddl tracker”] [release-version=v6.0.0-master] [git-hash=None] [git-branch=None] [go-version=go1.18.2] [utc-build-time=None] [race-enabled=false]
±–±---------------------------------------------±------------±-------+
| # | CHECK ITEM | TYPE | PASSED |
±–±---------------------------------------------±------------±-------+
| 1 | Source csv files size is proper | performance | true |
±–±---------------------------------------------±------------±-------+
| 2 | checkpoints are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 3 | table schemas are valid | critical | true |
±–±---------------------------------------------±------------±-------+
| 4 | Cluster is available | critical | true |
±–±---------------------------------------------±------------±-------+
| 5 | Lightning has the correct storage permission | critical | true |
±–±---------------------------------------------±------------±-------+

不知道是从头开始导入,还是接着之前的导入

这个问题我们检查一下代码。对于新任务,您可以暂时在任务配置中把 import-mode 设置为 loader,使用旧版的导入实现。

1 个赞

:+1:

后续可在这个 issue 上追踪

mark一下:https://github.com/pingcap/tiflow/issues/6133

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。