domain: record latest schema version after syncer restarted (#49929) #50248

ti-chi-bot · 2024-01-10T03:33:59Z

This is an automated cherry-pick of #49929

What problem does this PR solve?

Issue Number: close #49773

Problem Summary:

// tidb-0
[2024/01/02 09:38:06.869 +08:00] [INFO] [ddl.go:1063] ["start DDL job"] [category=ddl] [job="ID:415, Type:add index, State:queueing, SchemaState:none, SchemaID:102, TableID:245, RowCount:0, ArgLen:6, start time: 2024-01-02 09:38:06.845 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"] [query="alter table sbtest1 add index index_test_1704159486844 (c)"]
[2024/01/02 09:38:07.145 +08:00] [INFO] [ddl_worker.go:1030] ["run DDL job"] [worker="worker 6, tp add index"] [category=ddl] [jobID=415] [conn=3644851860] [category=ddl] [job="ID:415, Type:add index, State:running, SchemaState:write only, SchemaID:102, TableID:245, RowCount:0, ArgLen:0, start time: 2024-01-02 09:38:06.845 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/01/02 09:38:07.200 +08:00] [INFO] [domain.go:873] ["mdl gets lock, update to owner"] [jobID=415] [version=55]
...
[2024/01/02 09:39:02.947 +08:00] [INFO] [ddl_worker.go:1030] ["run DDL job"] [worker="worker 5, tp add index"] [category=ddl] [jobID=415] [conn=3644851860] [category=ddl] [job="ID:415, Type:add index, State:running, SchemaState:write reorganization, SchemaID:102, TableID:245, RowCount:0, ArgLen:0, start time: 2024-01-02 09:38:06.845 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:446735184611246206, UniqueWarnings:0"]
[2024/01/02 09:41:57.281 +08:00] [WARN] [repeatable_read.go:282] ["UpdateForUpdateTS failed"] [conn=3644851824] [session_alias=] [error="[tikv:9001]PD server timeout: "]
[2024/01/02 09:41:57.281 +08:00] [INFO] [conn.go:1132] ["command dispatched failed"] [conn=3644851824] [session_alias=] [connInfo="id:3644851824, addr:10.233.71.65:48912 status:11, collation:latin1_swedish_ci, user:root"] [command=Execute] [status="inTxn:1, autocommit:1"] [sql="UPDATE sbtest31 SET k=k+1 WHERE id=? [arguments: 35056900]"] [txn_mode=PESSIMISTIC] [timestamp=446735200326778960] [err="[tikv:9001]PD server timeout: \ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20231212100244-799fae176cfb/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20231212100244-799fae176cfb/normalize.go:164\ngithub.com/pingcap/tidb/pkg/store/driver/error.ToTiDBErr\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/store/driver/error/error.go:112\ngithub.com/pingcap/tidb/pkg/store/driver/txn.extractKeyErr\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/store/driver/txn/error.go:164\ngithub.com/pingcap/tidb/pkg/store/driver/txn.(*tikvTxn).extractKeyErr\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/store/driver/txn/txn_driver.go:322\ngithub.com/pingcap/tidb/pkg/store/driver/txn.(*tikvTxn).LockKeysFunc\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/store/driver/txn/txn_driver.go:93\ngithub.com/pingcap/tidb/pkg/session.(*LazyTxn).LockKeysFunc\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/session/txn.go:483\ngithub.com/pingcap/tidb/pkg/session.(*LazyTxn).LockKeys\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/session/txn.go:458\ngithub.com/pingcap/tidb/pkg/executor.doLockKeys\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/executor.go:1279\ngithub.com/pingcap/tidb/pkg/executor.(*PointGetExecutor).lockKeyBase\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/point_get.go:409\ngithub.com/pingcap/tidb/pkg/executor.(*PointGetExecutor).lockKeyIfNeeded\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/point_get.go:384\ngithub.com/pingcap/tidb/pkg/executor.(*PointGetExecutor).getAndLock\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/point_get.go:369\ngithub.com/pingcap/tidb/pkg/executor.(*PointGetExecutor).Next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/point_get.go:310\ngithub.com/pingcap/tidb/pkg/executor/internal/exec.Next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/internal/exec/executor.go:309\ngithub.com/pingcap/tidb/pkg/executor.(*UpdateExec).updateRows\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/update.go:266\ngithub.com/pingcap/tidb/pkg/executor.(*UpdateExec).Next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/update.go:240\ngithub.com/pingcap/tidb/pkg/executor/internal/exec.Next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/internal/exec/executor.go:309\ngithub.com/pingcap/tidb/pkg/executor.(*ExecStmt).next\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/adapter.go:1245\ngithub.com/pingcap/tidb/pkg/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/adapter.go:990\ngithub.com/pingcap/tidb/pkg/executor.(*ExecStmt).handlePessimisticDML\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/adapter.go:1051\ngithub.com/pingcap/tidb/pkg/executor.(*ExecStmt).handleNoDelay\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/adapter.go:813\ngithub.com/pingcap/tidb/pkg/executor.(*ExecStmt).Exec\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/executor/adapter.go:597\ngithub.com/pingcap/tidb/pkg/session.runStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/session/session.go:2386\ngithub.com/pingcap/tidb/pkg/session.(*session).ExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/session/session.go:2228\ngithub.com/pingcap/tidb/pkg/server.(*TiDBContext).ExecuteStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/driver_tidb.go:293\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).executePreparedStmtAndWriteResult\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/conn_stmt.go:305\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).executePlanCacheStmt\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/conn_stmt.go:233\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleStmtExecute\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/conn_stmt.go:224\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).dispatch\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/conn.go:1349\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/conn.go:1101\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/pkg/server/server.go:701\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1650\nUPDATE sbtest31 SET k=k+1 WHERE id=? [arguments: 35056900]"]
[2024/01/02 09:41:57.282 +08:00] [INFO] [txn.go:55] ["Try to create a new txn inside a transaction auto commit"] [conn=3644851824] [session_alias=] [schemaVersion=55] [txnStartTS=446735200326778960] [txnScope=global]

// tidb-1
[2024/01/02 09:42:24.022 +08:00] [INFO] [domain.go:873] ["mdl gets lock, update to owner"] [jobID=415] [version=56]
[2024/01/02 09:42:24.092 +08:00] [INFO] [index.go:911] ["index backfill state ready to merge"] [category=ddl] ["job ID"=415] [table=sbtest1] [index=index_test_1704159486844]
[2024/01/02 09:42:24.225 +08:00] [INFO] [domain.go:873] ["mdl gets lock, update to owner"] [jobID=415] [version=57]
[2024/01/02 09:42:24.318 +08:00] [INFO] [index.go:1959] ["start to merge temp index"] [category=ddl] [job="ID:415, Type:add index, State:running, SchemaState:write reorganization, SchemaID:102, TableID:245, RowCount:70000034, ArgLen:6, start time: 2024-01-02 09:38:06.845 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:446735251995361348, UniqueWarnings:0"] [reorgInfo="CurrElementType:_idx_,CurrElementID:2,StartKey:7480000000000000f55f69ffff000000000002,EndKey:7480000000000000f55f69ffff000000000002ff,First:false,PhysicalTableID:245,Ingest mode:false"]
[2024/01/02 09:42:25.610 +08:00] [INFO] [index.go:742] ["run add index job done"] [category=ddl] [charset=utf8mb4] [collation=utf8mb4_general_ci]
[2024/01/02 09:42:25.653 +08:00] [INFO] [domain.go:873] ["mdl gets lock, update to owner"] [jobID=415] [version=58]

// tidb-0
[2024/01/02 09:42:27.559 +08:00] [INFO] [domain.go:915] ["reload schema in loop, schema syncer need restart"]
[2024/01/02 09:42:27.559 +08:00] [INFO] [schema_validator.go:98] ["the schema validator stops"]
[2024/01/02 09:42:27.573 +08:00] [INFO] [schema_validator.go:129] ["the schema validator stopped before updating"]
[2024/01/02 09:42:27.573 +08:00] [INFO] [domain.go:973] ["mustReload succeed"]
[2024/01/02 09:42:27.573 +08:00] [INFO] [schema_validator.go:109] ["the schema validator restarts"]
[2024/01/02 09:42:27.573 +08:00] [INFO] [domain.go:936] ["schema syncer restarted"]
[2024/01/02 09:42:27.573 +08:00] [INFO] [domain.go:272] ["diff load InfoSchema success"] [currentSchemaVersion=55] [neededSchemaVersion=58] ["start time"=7.716326ms] [gotSchemaVersion=58] [phyTblIDs="[245,245,245]"] [actionTypes="[7,7,7]"] [diffTypes="[\"add index\",\"add index\",\"add index\"]"]
[2024/01/02 09:42:30.123 +08:00] [INFO] [ddl.go:1165] ["DDL job is finished"] [category=ddl] [jobID=415]

// tidb-0
[2024/01/02 09:42:30.135 +08:00] [INFO] [session.go:3925] [GENERAL_LOG] [conn=3644851796] [session_alias=] [user=root@10.233.71.65] [schemaVersion=58] [txnStartTS=446735253528903767] [forUpdateTS=446735253528903767] [isReadConsistency=false] [currentDB=sysbench_64_7000w] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="SELECT SUM(k) FROM sbtest1 WHERE id BETWEEN ? AND ? [arguments: (34975499, 34975598)] [arguments: (34975499, 34975598)]"]
[2024/01/02 09:42:30.135 +08:00] [INFO] [session.go:3925] [GENERAL_LOG] [conn=3644851824] [session_alias=] [user=root@10.233.71.65] [schemaVersion=55] [txnStartTS=446735253528903726] [forUpdateTS=446735253528903726][isReadConsistency=false] [currentDB=sysbench_64_7000w] [isPessimistic=true] [sessionTxnMode=PESSIMISTIC] [sql="DELETE FROM sbtest1 WHERE id=? [arguments: 45356626] [arguments: 45356626]"]

The start ts of two DML txns is close, but the schema version differs(55 v.s. 58). The txn with schemaVersion = 55 first obtains the info schema from the cache before the restoration of network partition (that is, the domain has not been successfully reloaded). When it commit later, because MDL is enabled, the schema validator check will be skipped, resulting in the commit of data under an old schema (index state is write-reorg, backfilling state is BackfillStateRunning, the write is redirected to temporary index), which further leads to inconsistent data indexes.

Here is the timeline:

Add index to tidb-0, change index status to delete-only.
Network partitioned between tidb-0 and PD, and tidb-1 is elected as the DDL owner.
tidb-1 continues to add indexes until public, schema version advances from 55 to 58.
tidb-0 network partition disappears, schema version is still 55.
tidb-0 executes DML using schema version 55 and commits.

What changed and how does it work?

When tidb-0 comes back, record the latest schema version in cache.
Check version in schema validator, return an error if a txn's schema version is too small.

Check List

Tests

Unit test
Integration test
Manual test (add detailed scripts or steps below)
No need to test
- I checked and no code files have been changed.

Side effects

Performance regression: Consumes more CPU
Performance regression: Consumes more Memory
Breaking backward compatibility

Documentation

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

Benjamin2037

LGTM

ti-chi-bot · 2024-02-19T08:16:30Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: Benjamin2037, tangenta

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~pkg/domain/OWNERS~~ [tangenta]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

ti-chi-bot · 2024-02-19T08:16:37Z

[LGTM Timeline notifier]

Timeline:

2024-01-10 08:40:26.340691868 +0000 UTC m=+432615.924945554: ☑️ agreed by Benjamin2037.
2024-02-19 08:16:36.213644772 +0000 UTC m=+258684.961267883: ☑️ agreed by tangenta.

tangenta · 2024-02-19T08:16:41Z

/retest

codecov · 2024-02-19T08:49:46Z

Codecov Report

❗ No coverage uploaded for pull request base (release-7.5@4a8c7b2). Click here to learn what that means.
The diff coverage is 58.3333%.

Additional details and impacted files

@@               Coverage Diff                @@
##             release-7.5     #50248   +/-   ##
================================================
  Coverage               ?   72.0438%           
================================================
  Files                  ?       1403           
  Lines                  ?     407603           
  Branches               ?          0           
================================================
  Hits                   ?     293653           
  Misses                 ?      94233           
  Partials               ?      19717

Flag	Coverage Δ
unit	`72.0438% <58.3333%> (?)`

Flags with carried forward coverage won't be shown. Click here to find out more.

Components	Coverage Δ
dumpling	`53.9913% <0.0000%> (?)`
parser	`∅ <0.0000%> (?)`
br	`53.3007% <0.0000%> (?)`

tangenta added 5 commits January 10, 2024 03:33

session: enable general log for sbtest1

45d3615

fail dml if schema version is too old

de9d62b

domain: record latest schema version after syncer restarted

4173d2d

fix TestSchemaValidator

1c36745

address comment

c23bfcb

ti-chi-bot mentioned this pull request Jan 10, 2024

domain: record latest schema version after syncer restarted #49929

Merged

13 tasks

ti-chi-bot added release-note-none size/S Denotes a PR that changes 10-29 lines, ignoring generated files. type/cherry-pick-for-release-7.5 labels Jan 10, 2024

ti-chi-bot bot added the do-not-merge/cherry-pick-not-approved label Jan 10, 2024

ti-chi-bot assigned tangenta Jan 10, 2024

Benjamin2037 approved these changes Jan 10, 2024

View reviewed changes

ti-chi-bot bot added the needs-1-more-lgtm label Jan 10, 2024

ti-chi-bot added the cherry-pick-approved Cherry pick PR approved by release team. label Jan 16, 2024

ti-chi-bot bot removed the do-not-merge/cherry-pick-not-approved label Jan 16, 2024

tangenta approved these changes Feb 19, 2024

View reviewed changes

ti-chi-bot bot added approved lgtm and removed needs-1-more-lgtm labels Feb 19, 2024

ti-chi-bot bot merged commit 3b7f150 into pingcap:release-7.5 Feb 19, 2024
17 of 18 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

domain: record latest schema version after syncer restarted (#49929) #50248

domain: record latest schema version after syncer restarted (#49929) #50248

ti-chi-bot commented Jan 10, 2024

Benjamin2037 left a comment

ti-chi-bot bot commented Feb 19, 2024

ti-chi-bot bot commented Feb 19, 2024

tangenta commented Feb 19, 2024

codecov bot commented Feb 19, 2024 •

edited

Loading

domain: record latest schema version after syncer restarted (#49929) #50248

domain: record latest schema version after syncer restarted (#49929) #50248

Conversation

ti-chi-bot commented Jan 10, 2024

What problem does this PR solve?

What changed and how does it work?

Check List

Release note

Benjamin2037 left a comment

Choose a reason for hiding this comment

ti-chi-bot bot commented Feb 19, 2024

ti-chi-bot bot commented Feb 19, 2024

[LGTM Timeline notifier]

tangenta commented Feb 19, 2024

codecov bot commented Feb 19, 2024 • edited Loading

Codecov Report

codecov bot commented Feb 19, 2024 •

edited

Loading