After stopping the full import in DM v6.1, restarting shows progress starting from zero, with no breakpoint resume

Translated
1

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

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

| username: Haaahei

[Environment]
TiDB v6.1.0
DM v6.1.0

[Problem]
Before executing stop-task:

image
image1380×604 97.6 KB

After executing stop-task, then executing start-task, waiting for N minutes, and then executing query-status:
image
image1380×610 98.7 KB

Task configuration:

image
image1380×498 108 KB

Related logs:

[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 run lightning”] [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

2
| username: lance6716 | Original post link

Could you upload the goroutine of this DM worker at this moment? We need to take a look at the issue.

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

3
| username: Haaahei | Original post link

[Attachment content cannot be directly translated. Please provide the text content you need translated.]

4
| username: lance6716 | Original post link

Thank you for the feedback. It looks like Lightning is still working normally, but it is not displaying the progress information correctly. You can check the row count of the table downstream to see if there has been any rollback.

We will investigate the issue with the progress information.

5
| username: Haaahei | Original post link

There is data being written downstream, but I don’t know if it’s starting from the beginning or continuing from where it left off. Moreover, after restarting the task, it takes a long time (7-8 minutes) before it actually starts writing data downstream.

6
| username: lance6716 | Original post link

Could you check if there are stdout/stderr files in the same directory as the DM worker logs? Is there any output in them? Please help upload them.

7
| username: Haaahei | Original post link

-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 |
±–±---------------------------------------------±------------±-------+

8
| username: lance6716 | Original post link

I don’t know whether to start importing from the beginning or continue from the previous import.

Let’s check the code for this issue. For new tasks, you can temporarily set the import-mode to loader in the task configuration to use the old import implementation.

9
| username: 西伯利亚狼 | Original post link

:+1:

10
| username: guominghao | Original post link

You can track this issue going forward.

11
| username: Haaahei | Original post link

Mark: lightning loader progress reset to 0% after restart task · Issue #6133 · pingcap/tiflow · GitHub

12
| username: system | Original post link

This topic was automatically closed 1 minute after the last reply. No new replies are allowed.