search

pingcap / tidb

TiDB - the open-source, cloud-native, distributed SQL database designed for modern applications.
https://pingcap.com
Apache License 2.0
37.27k stars 5.84k forks source link

Create table causes too much time when tidb_scatter_region is enabled #24295

Open rleungx opened 3 years ago

rleungx commented 3 years ago

Bug Report

scatter table region：

[2021/04/25 10:37:03.844 +08:00] [INFO] [split_region.go:60] ["split batch regions request"] ["split key count"=8] ["batch count"=1] ["first batch, region ID"=65836666] ["first split key"=748000000000017236]
[2021/04/25 10:37:03.849 +08:00] [INFO] [split_region.go:157] ["batch split regions complete"] ["batch region ID"=65836666] ["first at"=748000000000017236] ["first new region left"="{Id:66264684 StartKey:7480000000000172ff345f72f000000000ff0000000000000000fa EndKey:748000
0000000172ff3600000000000000f8 RegionEpoch:{ConfVer:1013 Version:62875} Peers:[id:66264685 store_id:17  id:66264686 store_id:1  id:66264687 store_id:6323527 ]}"] ["new region count"=8]
[2021/04/25 10:37:04.294 +08:00] [INFO] [split_region.go:215] ["start scatter region"] [regionID=66264688]
[2021/04/25 10:37:04.295 +08:00] [INFO] [split_region.go:177] ["batch split regions, scatter region complete"] ["batch region ID"=65836666] [at=7480000000000172365f729000000000000000] ["new region left"="{Id:66264688 StartKey:7480000000000172ff3600000000000000f8 EndKey:7480000000000172ff365f729000000000ff0000000000000000fa RegionEpoch:{ConfVer:1013 Version:62875} Peers:[id:66264689 store_id:17  id:66264690 store_id:1  id:66264691 store_id:6323527 ]}"]
[2021/04/25 10:37:04.303 +08:00] [INFO] [split_region.go:209] ["split regions complete"] ["region count"=8] ["region IDs"="[66264684,66264688,66264692,66264696,66264700,66264704,66264708,66264712]"]

scatter index region:

[2021/04/25 10:37:04.303 +08:00] [INFO] [split_region.go:60] ["split batch regions request"] ["split key count"=8] ["batch count"=1] ["first batch, region ID"=65836666] ["first split key"=7480000000000172365f698000000000000001]
[2021/04/25 10:37:04.309 +08:00] [INFO] [split_region.go:157] ["batch split regions complete"] ["batch region ID"=66264688] ["first at"=7480000000000172365f698000000000000001] ["first new region left"="{Id:66264737 StartKey:7480000000000172ff3600000000000000f8 EndKey:7480000000000172ff365f698000000000ff0000010000000000fa RegionEpoch:{ConfVer:1014 Version:62883} Peers:[id:66264738 store_id:17  id:66264739 store_id:1  id:66264740 store_id:6323527  id:66264741 store_id:15 is_learner:true ]}"] ["new region count"=8]
[2021/04/25 10:37:04.309 +08:00] [INFO] [split_region.go:215] ["start scatter region"] [regionID=66264737]
[2021/04/25 10:41:05.297 +08:00] [WARN] [backoff.go:318] ["pdRPC backoffer.maxSleep 240000ms is exceeded, errors:\nrpc error: code = Unknown desc = region 66264737 is not fully replicated at 2021-04-25T10:41:00.780778177+08:00\nrpc error: code = Unknown desc = region 6626
4737 is not fully replicated at 2021-04-25T10:41:02.854346592+08:00\nrpc error: code = Unknown desc = region 66264737 is not fully replicated at 2021-04-25T10:41:05.297772999+08:00"]
[2021/04/25 10:41:05.297 +08:00] [INFO] [split_region.go:184] ["batch split regions, scatter region failed"] ["batch region ID"=66264688] [at=7480000000000172365f698000000000000001] ["new region left"="{Id:66264737 StartKey:7480000000000172ff3600000000000000f8 EndKey:7480
000000000172ff365f698000000000ff0000010000000000fa RegionEpoch:{ConfVer:1014 Version:62883} Peers:[id:66264738 store_id:17  id:66264739 store_id:1  id:66264740 store_id:6323527  id:66264741 store_id:15 is_learner:true ]}"] [error="[tikv:9005]Region is unavailable"]

pd:


[2021/04/25 10:37:44.677 +08:00] [INFO] [operator_controller.go:424] ["add operator"] [region-id=66264688] [operator="\"scatter-region {mv light peer: store [1 6323527 17] to [18 15 7]} (kind:leader,region, region:66264688(62875,1013), createAt:2021-04-25 10:37:44.677325226 +0800 CST m=+171744.998618915, startAt:0001-01-01 00:00:00 +0000 UTC, currentStep:0, steps:[add learner peer 66264717 on store 15, promote learner peer 66264717 on store 15 to voter, remove peer on store 17, add learner peer 66264718 on store 7, promote learner peer 66264718 on store 7 to voter, remove peer on store 6323527, add learner peer 66264716 on store 18, promote learner pqeer 66264716 on store 18 to voter, transfer leader from store 1 to store 15, remove peer on store 1])\""] ["additional info"=]
[2021/04/25 10:37:44.677 +08:00] [INFO] [operator_controller.go:620] ["send schedule command"] [region-id=66264688] [step="add learner peer 66264717 on store 15"] [source=create]
[2021/04/25 10:37:44.682 +08:00] [INFO] [cluster.go:551] ["region ConfVer changed"] [region-id=66264688] [detail="Add peer:{id:66264717 store_id:15 is_learner:true }"] [old-confver=1013] [new-confver=1014]
[2021/04/25 10:37:44.692 +08:00] [INFO] [cluster_worker.go:217] ["region batch split, generate new regions"] [region-id=66264688] [origin="id:66264737 start_key:\"7480000000000172FF3600000000000000F8\" end_key:\"7480000000000172FF365F698000000000FF0000010000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264738 store_id:17 > peers:<id:66264739 store_id:1 > peers:<id:66264740 store_id:6323527 > peers:<id:66264741 store_id:15 is_learner:true > id:66264742 start_key:\"7480000000000172FF365F698000000000FF0000010000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000020000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264743 store_id:17 > peers:<id:66264744 store_id:1 > peers:<id:66264745 store_id:6323527 > peers:<id:66264746 store_id:15 is_learner:true > id:66264747 start_key:\"7480000000000172FF365F698000000000FF0000020000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000030000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264748 store_id:17 > peers:<id:66264749 store_id:1 > peers:<id:66264750 store_id:6323527 > peers:<id:66264751 store_id:15 is_learner:true > id:66264752 start_key:\"7480000000000172FF365F698000000000FF0000030000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000040000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264753 store_id:17 > peers:<id:66264754 store_id:1 > peers:<id:66264755 store_id:6323527 > peers:<id:66264756 store_id:15 is_learner:true > id:66264757 start_key:\"7480000000000172FF365F698000000000FF0000040000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000050000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264758 store_id:17 > peers:<id:66264759 store_id:1 > peers:<id:66264760 store_id:6323527 > peers:<id:66264761 store_id:15 is_learner:true > id:66264762 start_key:\"7480000000000172FF365F698000000000FF0000050000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000060000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264763 store_id:17 > peers:<id:66264764 store_id:1 > peers:<id:66264765 store_id:6323527 > peers:<id:66264766 store_id:15 is_learner:true > id:66264767 start_key:\"7480000000000172FF365F698000000000FF0000060000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000070000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264768 store_id:17 > peers:<id:66264769 store_id:1 > peers:<id:66264770 store_id:6323527 > peers:<id:66264771 store_id:15 is_learner:true > id:66264772 start_key:\"7480000000000172FF365F698000000000FF0000070000000000FA\" end_key:\"7480000000000172FF365F698000000000FF0000080000000000FA\" region_epoch:<conf_ver:1014 version:62883 > peers:<id:66264773 store_id:17 > peers:<id:66264774 store_id:1 > peers:<id:66264775 store_id:6323527 > peers:<id:66264776 store_id:15 is_learner:true >"] [total=8]
[2021/04/25 10:37:55.008 +08:00] [INFO] [operator_controller.go:537] ["operator finish"] [region-id=66264688] [takes=10.331249526s] [operator="\"scatter-region {mv light peer: store [1 6323527 17] to [18 15 7]} (kind:leader,region, region:66264688(62875,1013), createAt:2021-04-25 10:37:44.677325226 +0800 CST m=+171744.998618915, startAt:2021-04-25 10:37:44.67754199 +0800 CST m=+171744.998835677, currentStep:10, steps:[add learner peer 66264717 on store 15, promote learner peer 66264717 on store 15 to voter, remove peer on store 17, add learner peer 66264718 on store 7, promote learner peer 66264718 on store 7 to voter, remove peer on store 6323527, add learner peer 66264716 on store 18, promote learner peer 66264716 on store 18 to voter, transfer leader from store 1 to store 15, remove peer on store 1]) finished\""] ["additional info"=]

The reason could be when splitting the index region, the scatter operation is working on the same region in handling the table region process. It will add a learner when doing the scatter process, which may cause an extra peer problem when splitting the index region. Under this situation, PD cannot scatter the index region with 4 peers because the region is not fully replicated. See: https://github.com/tikv/pd/blob/v4.0.8/server/schedule/opt/healthy.go#L51

And finally, the operation failed which leads to a long time to create a table.

It exists in both 5.0 and 4.0.

rleungx commented 3 years ago

More actions can be found in: https://github.com/tikv/pd/issues/2733