DM task not in synced status after import full data with lighting physical backend

[fubinzh]

What did you do?

1. Deploy cluster with 2 mysql upstream, and 3 DM.
2. Run ycsb workload to prepare ~100GB data for each upstream
3. Start DM task using lightning physical backend to migrate upstream to TiDB

[root@dm-dm-master-0 /]# cat /tmp/testcases/dm_lightning_physical_backend_sharding/config/task.yaml
---
name: dm_lightning_physical_sharding
task-mode: all
is-sharding: true
shard-mode: "optimistic"
meta-schema: "dm_meta"

loaders:
    global:
        pool-size: 16
        dir: "/var/lib/dm-worker/dumped_data"
        import-mode: "physical" # lightning local mode  https://github.com/pingcap/docs-cn/pull/12296/files
        sorting-dir-physical: "/var/lib/dm-worker/dumped_data"
        on-duplicate-physical: "none"
        disk-quota-physical: "0"
        checksum-physical: "required"

target-database:
    host: "downstream-tidb"
    port: 4000
    user: "root"
    password: ""

mysql-instances:
    - source-id: "source-0"
      block-allow-list: "instance"
      loader-config-name: "global"
    - source-id: "source-1"
      block-allow-list: "instance"
      loader-config-name: "global"

block-allow-list:
    instance:
        do-dbs: ["test"]

4. check DM task status

What did you expect to see?

DM should migrate full data to TiDB correctly, and after that DM task should be in "Synced" status

What did you see instead?

DM migrate full data to TiDB using physical backend, however after that DM tasks is still "synced": false for one of the DM sources.

[root@dm-dm-master-0 /]# /dmctl --master-addr=127.0.0.1:8261 query-status dm_lightning_physical_sharding
{
    "result": true,
    "msg": "",
    "sources": [
        {
            "result": true,
            "msg": "",
            "sourceStatus": {
                "source": "source-0",
                "worker": "dm-dm-worker-1",
                "result": null,
                "relayStatus": null
            },
            "subTaskStatus": [
                {
                    "name": "dm_lightning_physical_sharding",
                    "stage": "Running",
                    "unit": "Sync",
                    "result": null,
                    "unresolvedDDLLockID": "",
                    "sync": {
                        "totalEvents": "7007540",
                        "totalTps": "299",
                        "recentTps": "0",
                        "masterBinlog": "(mysql-bin.000124, 316637597)",
                        "masterBinlogGtid": "c2e04805-a490-11ed-a1c1-aaf72f6a8cf3:1-100000003",
                        "syncerBinlog": "(mysql-bin.000124, 316637442)",
                        "syncerBinlogGtid": "c2e04805-a490-11ed-a1c1-aaf72f6a8cf3:1-100000002",
                        "blockingDDLs": [
                        ],
                        "unresolvedGroups": [
                        ],
                        "synced": false,
                        "binlogType": "remote",
                        "secondsBehindMaster": "0",
                        "blockDDLOwner": "",
                        "conflictMsg": "",
                        "totalRows": "7007540",
                        "totalRps": "299",
                        "recentRps": "0"
                    },
                    "validation": null
                }
            ]
        },
                {
            "result": true,
            "msg": "",
            "sourceStatus": {
                "source": "source-1",
                "worker": "dm-dm-worker-0",
                "result": null,
                "relayStatus": null
            },
            "subTaskStatus": [
                {
                    "name": "dm_lightning_physical_sharding",
                    "stage": "Running",
                    "unit": "Sync",
                    "result": null,
                    "unresolvedDDLLockID": "",
                    "sync": {
                        "totalEvents": "443",
                        "totalTps": "0",
                        "recentTps": "0",
                        "masterBinlog": "(mysql-bin.000124, 616624074)",
                        "masterBinlogGtid": "c2ec66cc-a490-11ed-bcd4-4e0daec8cb58:1-100000003",
                        "syncerBinlog": "(mysql-bin.000124, 616624074)",
                        "syncerBinlogGtid": "c2ec66cc-a490-11ed-bcd4-4e0daec8cb58:1-100000003",
                        "blockingDDLs": [
                        ],
                        "unresolvedGroups": [
                        ],
                        "synced": true,
                        "binlogType": "remote",
                        "secondsBehindMaster": "0",
                        "blockDDLOwner": "",
                        "conflictMsg": "",
                        "totalRows": "443",
                        "totalRps": "0",
                        "recentRps": "0"
                    },
                    "validation": null
                }
            ]
        }
    ]
}

We can see that "analyze table xx" is not synced to TiDB

mysql> show binlog events in 'mysql-bin.000124' from 316637442;
+------------------+-----------+------------+-----------+-------------+---------------------------------------------------------------------------+
| Log_name         | Pos       | Event_type | Server_id | End_log_pos | Info                                                                      |
+------------------+-----------+------------+-----------+-------------+---------------------------------------------------------------------------+
| mysql-bin.000124 | 316637442 | Gtid       |         2 |   316637507 | SET @@SESSION.GTID_NEXT= 'c2e04805-a490-11ed-a1c1-aaf72f6a8cf3:100000003' |
| mysql-bin.000124 | 316637507 | Query      |         2 |   316637597 | use `test`; ANALYZE TABLE usertable                                       |
+------------------+-----------+------------+-----------+-------------+---------------------------------------------------------------------------+
2 rows in set (0.00 sec)

If I execute an DML on this upstream, then the DM task is synced to TiDB.

Versions of the cluster

DM version (run dmctl -V or dm-worker -V or dm-master -V):

[root@dm-dm-master-0 /]# /dm-master -V
Release Version: v6.6.0-alpha
Git Commit Hash: 84a76a88348b2bbf760a81e42ef2f5a3b0182dbc
Git Branch: heads/refs/tags/v6.6.0-alpha
UTC Build Time: 2023-02-03 09:47:03
Go Version: go version go1.19.5 linux/amd64
Failpoint Build: false

Upstream MySQL/MariaDB server version:

mysql> select version();
+------------+
| version()  |
+------------+
| 5.7.36-log |
+------------+
1 row in set (0.00 sec)

Downstream TiDB cluster version (execute SELECT tidb_version(); in a MySQL client):

(paste TiDB cluster version here)

How did you deploy DM: tiup or manually?

ti-operator

current status of DM cluster (execute query-status <task-name> in dmctl)

(paste current status of DM cluster here)

[fubinzh]

/severity Major

[lance6716]

lightning in DM will not run analyze. And what the binlog event at (mysql-bin.000124, 316637597) on source-0? And what's the log of the DM-worker that processes (mysql-bin.000124, 316637597)?

[fubinzh]

lightning in DM will not run analyze. And what the binlog event at (mysql-bin.000124, 316637597) on source-0? And what's the log of the DM-worker that processes (mysql-bin.000124, 316637597)?

mysql> show binlog events in 'mysql-bin.000124' from 316637442;
+------------------+-----------+------------+-----------+-------------+---------------------------------------------------------------------------+
| Log_name         | Pos       | Event_type | Server_id | End_log_pos | Info                                                                      |
+------------------+-----------+------------+-----------+-------------+---------------------------------------------------------------------------+
| mysql-bin.000124 | 316637442 | Gtid       |         2 |   316637507 | SET @@SESSION.GTID_NEXT= 'c2e04805-a490-11ed-a1c1-aaf72f6a8cf3:100000003' |
| mysql-bin.000124 | 316637507 | Query      |         2 |   316637597 | use `test`; ANALYZE TABLE usertable                                       |
+------------------+-----------+------------+-----------+-------------+---------------------------------------------------------------------------+
2 rows in set (0.00 sec)

[lance6716]

we can see the last event (316637597) is Query event, so it's the same cause as #3928

[fubinzh]

/found automation