Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ddl: include ddl sessions in session manager's internal list #42897

Merged
merged 2 commits into from
Apr 11, 2023

Conversation

tangenta
Copy link
Contributor

What problem does this PR solve?

Issue Number: close #42895

Problem Summary:

The session used by the internal transaction of DDL is not added to the session manager (StoreInternalSession), which causes the min start TS reporter to be unaware of the DDL transaction when updating the metadata on etcd, so that GC safepoint will move forward, which will further lead to the failure of the DDL transaction.

This problem will be more obvious when the DDL transaction takes a long time to execute, especially when creating index in ingest mode. If the import process takes more than 10 minutes, it will almost certainly trigger this error.

What is changed and how it works?

Add the DDL session to the session manager.

Check List

Tests

  • Unit test
  • Integration test
  • Manual test (add detailed scripts or steps below)
    [2023/04/10 16:53:58.872 +08:00] [INFO] [local.go:1394] ["put job back to jobCh to retry later"] [startKey=74800000000000005A5F6980000000000000010380000000004C83BC0380000000005B49AA] [endKey=74800000000000005A5F6980000000000000010380000000004C84ED03800000000015537A] [stage=wrote] [retryCount=4] [waitUntil=2023/04/10 16:54:14.872 +08:00]
    [2023/04/10 16:53:58.872 +08:00] [WARN] [region_job.go:377] ["meet error and handle the job later"] ["job stage"=wrote] [error="[Lightning:KV:ServerIsBusy]too many sst files are ingesting"] [region="{ID=180,startKey=7480000000000000FF5A5F698000000000FF0000010380000000FF004C1E9803800000FF000002118E000000FC,endKey=7480000000000000FF5A5F698000000000FF0000010380000000FF004C1FC503800000FF00007DD35F000000FC,epoch=\"conf_ver:1 version:66 \",peers=\"id:181 store_id:1 \"}"] [start=74800000000000005A5F6980000000000000010380000000004C1E9803800000000002118E] [end=74800000000000005A5F6980000000000000010380000000004C1FC50380000000007DD35F]
    [2023/04/10 16:53:58.872 +08:00] [INFO] [local.go:1394] ["put job back to jobCh to retry later"] [startKey=74800000000000005A5F6980000000000000010380000000004C1E9803800000000002118E] [endKey=74800000000000005A5F6980000000000000010380000000004C1FC50380000000007DD35F] [stage=wrote] [retryCount=4] [waitUntil=2023/04/10 16:54:14.872 +08:00]
    [2023/04/10 16:53:58.872 +08:00] [INFO] [local.go:1417] ["import engine pending jobs"] [count=14]
    [2023/04/10 16:53:58.872 +08:00] [INFO] [local.go:1050] ["import engine unfinished ranges"] [count=0]
    [2023/04/10 16:54:00.647 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694693065392128] [StartTSLowerLimit=440672043823792128]
    [2023/04/10 16:54:00.647 +08:00] [INFO] [info.go:822] [ReportMinStartTS] ["Internal Session Transaction StartTS"=440694686144790540]
    [2023/04/10 16:54:18.878 +08:00] [INFO] [local.go:1394] ["put job back to jobCh to retry later"] [startKey=74800000000000005A5F6980000000000000010380000000005187880380000000004197FF] [endKey=74800000000000005A5F69800000000000000103800000000051F665038000000000026084] [stage=wrote] [retryCount=5] [waitUntil=2023/04/10 16:54:48.878 +08:00]
    [2023/04/10 16:54:18.878 +08:00] [WARN] [region_job.go:377] ["meet error and handle the job later"] ["job stage"=wrote] [error="[Lightning:KV:ServerIsBusy]too many sst files are ingesting"] [region="{ID=178,startKey=7480000000000000FF5A5F698000000000FF0000010380000000FF004BEBFE03800000FF00003253DD000000FC,endKey=7480000000000000FF5A5F698000000000FF0000010380000000FF004BED2E03800000FF000023488A000000FC,epoch=\"conf_ver:1 version:66 \",peers=\"id:179 store_id:1 \"}"] [start=74800000000000005A5F6980000000000000010380000000004BEBFE0380000000003253DD] [end=74800000000000005A5F6980000000000000010380000000004BED2E03800000000023488A]
    [2023/04/10 16:54:18.878 +08:00] [INFO] [local.go:1394] ["put job back to jobCh to retry later"] [startKey=74800000000000005A5F6980000000000000010380000000004BEBFE0380000000003253DD] [endKey=74800000000000005A5F6980000000000000010380000000004BED2E03800000000023488A] [stage=wrote] [retryCount=5] [waitUntil=2023/04/10 16:54:48.878 +08:00]
    
    ...
    
    [2023/04/10 16:54:28.654 +08:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.000227208s] [conn=1062748356989682073] [user=root] [database=sbtest] [txn_start_ts=0] [mem_max="126976 Bytes (124 KB)"] [sql="CREATE INDEX k_1 ON sbtest1(k)"]
    [2023/04/10 16:54:30.649 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694700929712128] [StartTSLowerLimit=440672051688112128]
    [2023/04/10 16:54:30.650 +08:00] [INFO] [info.go:822] [ReportMinStartTS] ["Internal Session Transaction StartTS"=440694686144790540]
    
    We can see the Internal Session Transaction StartTS is unchanged during the import. After adding the index, the minimum start TS continues to advance:
    [2023/04/10 16:54:50.456 +08:00] [INFO] [ddl.go:1164] ["[ddl] DDL job is finished"] [jobID=92]
    [2023/04/10 16:54:50.457 +08:00] [INFO] [callback.go:128] ["performing DDL change, must reload"]
    [2023/04/10 16:54:51.898 +08:00] [INFO] [update.go:1195] ["[stats] auto analyze for unanalyzed"] [sql="analyze table `sbtest`.`sbtest1` index `k_1`"]
    [2023/04/10 16:54:55.773 +08:00] [INFO] [coprocessor.go:1262] ["[TIME_COP_PROCESS] resp_time:338.637833ms txnStartTS:18446744073709551615 region_id:138 store_addr:127.0.0.1:20160 kv_process_ms:336 kv_wait_ms:0 kv_read_ms:0 processed_versions:410870 total_versions:410871 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:410870 rocksdb_cache_hit_count:2 rocksdb_read_count:3001 rocksdb_read_byte:39644938"]
    [2023/04/10 16:54:56.106 +08:00] [INFO] [coprocessor.go:1262] ["[TIME_COP_PROCESS] resp_time:332.771333ms txnStartTS:18446744073709551615 region_id:140 store_addr:127.0.0.1:20160 kv_process_ms:331 kv_wait_ms:0 kv_read_ms:0 processed_versions:410871 total_versions:410872 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:410871 rocksdb_cache_hit_count:2 rocksdb_read_count:3001 rocksdb_read_byte:39641119"]
    ...
    [2023/04/10 16:54:58.801 +08:00] [INFO] [coprocessor.go:1262] ["[TIME_COP_PROCESS] resp_time:326.515625ms txnStartTS:18446744073709551615 region_id:22 store_addr:127.0.0.1:20160 kv_process_ms:324 kv_wait_ms:0 kv_read_ms:0 processed_versions:549986 total_versions:549987 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:549986 rocksdb_cache_hit_count:3 rocksdb_read_count:1353 rocksdb_read_byte:44061302"]
    [2023/04/10 16:54:59.287 +08:00] [INFO] [handle.go:1412] ["[stats] incrementally update modifyCount"] [tableID=90] [curModifyCnt=1443200] [results.BaseModifyCnt=1443200] [modifyCount=0]
    [2023/04/10 16:54:59.287 +08:00] [INFO] [handle.go:1434] ["[stats] directly update count"] [tableID=90] [results.Count=10000000] [count=10000000]
    [2023/04/10 16:54:59.464 +08:00] [INFO] [analyze.go:590] ["analyze table `sbtest`.`sbtest1` has finished"] [partition=] ["job info"="auto analyze table all columns with 256 buckets, 500 topn, 0.010449541160647636 samplerate"] ["start time"=2023/04/10 16:54:51.909 +08:00] ["end time"=2023/04/10 16:54:59.463 +08:00] [cost=7.553206458s]
    [2023/04/10 16:55:00.362 +08:00] [INFO] [domain.go:2604] ["refreshServerIDTTL succeed"] [serverID=483282] ["lease id"=2231876a59be3a5d]
    [2023/04/10 16:55:00.648 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694708794294272] [StartTSLowerLimit=440672059552694272]
    [2023/04/10 16:55:30.648 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694716658614272] [StartTSLowerLimit=440672067417014272]
    [2023/04/10 16:56:00.648 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694724523196416] [StartTSLowerLimit=440672075281596416]
    [2023/04/10 16:56:30.649 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694732387516416] [StartTSLowerLimit=440672083145916416]
    [2023/04/10 16:57:00.649 +08:00] [INFO] [info.go:813] [ReportMinStartTS] ["initial minStartTS"=440694740251836416] [StartTSLowerLimit=440672091010236416]
    
  • No code

Side effects

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

Documentation

  • Affects user behaviors
  • Contains syntax changes
  • Contains variable changes
  • Contains experimental features
  • Changes MySQL compatibility

Release note

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

None

@ti-chi-bot
Copy link
Member

ti-chi-bot commented Apr 10, 2023

[REVIEW NOTIFICATION]

This pull request has been approved by:

  • Benjamin2037
  • zimulala

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

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

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

@ti-chi-bot ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Apr 10, 2023
Copy link
Collaborator

@Benjamin2037 Benjamin2037 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@ti-chi-bot ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Apr 10, 2023
Copy link
Contributor

@zimulala zimulala left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@ti-chi-bot ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Apr 11, 2023
@tangenta
Copy link
Contributor Author

/merge

@ti-chi-bot
Copy link
Member

This pull request has been accepted and is ready to merge.

Commit hash: 7d04b60

@ti-chi-bot ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Apr 11, 2023
@hawkingrei
Copy link
Member

/retest

@ti-chi-bot ti-chi-bot merged commit a20e7fd into pingcap:master Apr 11, 2023
@ti-chi-bot
Copy link
Member

@tangenta: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name Commit Details Required Rerun command
idc-jenkins-ci-tidb/check_dev_2 6b7734c link true /test check-dev2
idc-jenkins-ci-tidb/unit-test 7d04b60 link unknown /test unit-test

Full PR test history. Your PR dashboard.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
release-note-none Denotes a PR that doesn't merit a release note. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

DDL internal txn reports "GC life time is shorter than transaction duration"
5 participants