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

*: add execution retry count in slow log and slow_query (#19487) #20494

Merged
merged 5 commits into from
Oct 19, 2020

Conversation

ti-srebot
Copy link
Contributor

cherry-pick #19487 to release-4.0


Signed-off-by: crazycs520 crazycs520@gmail.com

What problem does this PR solve?

# Time: 2020-08-26T19:05:13.798533+08:00
# Txn_start_ts: 419021432206655496
# User@Host: root[root] @ 127.0.0.1 [127.0.0.1]
# Conn_ID: 154
# Query_time: 2.108649633
# Parse_time: 0.00006201
# Compile_time: 0.00016432
# Rewrite_time: 0.00005131
# Optimize_time: 0.00008422
# Wait_TS: 0.00014764
# Cop_time: 0.024715072 Process_time: 0.025 Request_count: 1 Total_keys: 106673 Process_keys: 106644
# DB: test
# Is_internal: false
# Digest: ae2284349b91ac35a65de57f0f6a7e3f72fae63b2128e61d55633aff8bc27f82
# Stats: t:pseudo
# Num_cop_tasks: 1
# Cop_proc_avg: 0.025 Cop_proc_addr: 127.0.0.1:20160
# Cop_wait_avg: 0 Cop_wait_addr: 127.0.0.1:20160
# Mem_max: 1426
# Prepared: false
# Plan_from_cache: false
# Has_more_results: false
# KV_total: 2.098782806
# PD_total: 0
# Backoff_total: 0
# Write_sql_response_total: 0.00000146
# Succ: true
# Plan: tidb_decode_plan('5AQ0MAkzXzUJMAkwLjMzMjMuAQAoCXRlc3QudC5hLCANCvBGYgk0CXRpbWU6MjUuNTQwNzUxbXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkxLjA4OTg0Mzc1IEtCCU4vQQoxCTI2XzZWbgAkZm9yIHVwZGF0ZS5mAAwzNzkyLmYADAlOL0EBBBgKMgkzMV85VksAPGRhdGE6U2VsZWN0aW9uXzgVURw0LjczNzMwMjK3AHhjb3BfdGFzazoge251bTogMSwgbWF4OjI0LjY3ODAxBS1YcHJvY19rZXlzOiAxMDY2NDQsIHJwY18RMAEMJRkAIAU2RDEyNTJtc30JMzA4IEJ5dGVzCQH9IDMJMV84CTFfME5sAQhsdCgtZSRhLCA1KQkzMjAJAXUFiwQzMwGxDG1pbjopDBRwODA6MjgBFBRwOTU6MzABCiRpdGVyczo4MCwgAcwBCgF1AQQYCjQJMTBfNwV6sDEJdGFibGU6dCwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvCTQwMP6BABWB')
# Plan_digest: ccba66308841bddbc1eae0da8a4b4d50773113ad1d6ca8b7bc50091a1ea5f8bf
use test;
select * from t where a<5 for update;

The parse,compile,rewrite,optimize time are very fast, check the plan and the execution time is also very fast,

It's hard to find out the reason of this slow log, Why it spend too much time?

test> select tidb_decode_plan('5AQ0MAkzXzUJMAkwLjMzMjMuAQAoCXRlc3QudC5hLCANCvBGYgk0CXRpbWU6MjUuNTQwNzUxbXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkxLjA4OTg0Mzc1IEtCCU4vQQoxCTI2XzZWbgAkZm9yIHVwZGF0ZS5mAAwzNzkyLmYADAlOL0EBBBgKMgkzMV85VksAPGRhdGE6U2VsZWN0aW9uXzgVURw0LjczNzMwMjK3AHhjb3BfdGFzazoge251bTogMSwgbWF4OjI0LjY3ODAxBS1YcHJvY19rZXlzOiAxMDY2NDQsIHJwY18RMAEMJRkAIAU2RDEyNTJtc30JMzA4IEJ5dGVzCQH9IDMJMV84CTFfME5sAQhsdCgtZ
   -> SRhLCA1KQkzMjAJAXUFiwQzMwGxDG1pbjopDBRwODA6MjgBFBRwOTU6MzABCiRpdGVyczo4MCwgAcwBCgF1AQQYCjQJMTBfNwV6sDEJdGFibGU6dCwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvCTQwMP6BABWB');
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('5AQ0MAkzXzUJMAkwLjMzMjMuAQAoCXRlc3QudC5hLCANCvBGYgk0CXRpbWU6MjUuNTQwNzUxbXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkxLjA4OTg0Mzc1IEtCCU4vQQoxCTI2XzZWbgAkZm9yIHVwZGF0ZS5mAAwzNzkyLmYADAlOL0EBBBgKMgkzMV85VksAPGRhdGE6U2VsZWN0aW9uXzgVURw0LjczNzMwMj  |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|     id                     task         estRows               operator info                              actRows    execution info                                                                                                          memory           disk |
|     Projection_5           root         0.3323333333333333    test.t.a, test.t.b                         4          time:25.540751ms, loops:2, Concurrency:OFF                                                                              1.08984375 KB    N/A  |
|     └─SelectLock_6         root         0.3323333333333333    for update                                 4          time:25.537921ms, loops:2                                                                                               N/A              N/A  |
|       └─TableReader_9      root         0.3323333333333333    data:Selection_8                           4          time:24.737302ms, loops:2, cop_task: {num: 1, max:24.678012ms, proc_keys: 106644, rpc_num: 1, rpc_time: 24.671252ms}    308 Bytes        N/A  |
|         └─Selection_8      cop[tikv]    0.3323333333333333    lt(test.t.a, 5)                            320        proc max:33ms, min:21ms, p80:28ms, p95:30ms, iters:80, tasks:80                                                         N/A              N/A  |
|           └─TableScan_7    cop[tikv]    1                     table:t, keep order:false, stats:pseudo    400        proc max:33ms, min:21ms, p80:28ms, p95:30ms, iters:80, tasks:80                                                         N/A              N/A  |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

The reason is, lock write conflict, and then re-execute this statement.

So this PR record the execution retry count in slow log and slow_query.

# Time: 2020-08-26T19:18:34.365549+08:00
# Txn_start_ts: 419021641709518854
# User@Host: root[root] @ 127.0.0.1 [127.0.0.1]
# Conn_ID: 9
# Exec_retry_count: 57
# Query_time: 3.49034938
# Parse_time: 0.0000823
...

Related changes

  • PR to update pingcap/docs/pingcap/docs-cn:
  • Need to cherry-pick to the release branch

Check List

Tests

  • Unit test

Side effects

  • Performance regression
    • Consumes more CPU
    • Consumes more MEM

Release note

  • Add execution retry count in slow log and slow_query.

Signed-off-by: ti-srebot <ti-srebot@pingcap.com>
@ti-srebot
Copy link
Contributor Author

/run-all-tests

Signed-off-by: crazycs520 <crazycs520@gmail.com>
Copy link
Contributor

@AilinKid AilinKid 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-srebot ti-srebot added the status/LGT1 Indicates that a PR has LGTM 1. label Oct 19, 2020
@crazycs520
Copy link
Contributor

/run-all-tests

Copy link
Contributor

@qw4990 qw4990 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-srebot ti-srebot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Oct 19, 2020
@crazycs520
Copy link
Contributor

/run-all-tests

@crazycs520
Copy link
Contributor

/merge

@ti-srebot ti-srebot added the status/can-merge Indicates a PR has been approved by a committer. label Oct 19, 2020
@ti-srebot
Copy link
Contributor Author

/run-all-tests

@ti-srebot
Copy link
Contributor Author

@ti-srebot merge failed.

Copy link
Contributor

@tangenta tangenta 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-srebot ti-srebot added status/LGT3 The PR has already had 3 LGTM. and removed status/LGT2 Indicates that a PR has LGTM 2. labels Oct 19, 2020
@crazycs520
Copy link
Contributor

/merge

@ti-srebot
Copy link
Contributor Author

/run-all-tests

@ti-srebot
Copy link
Contributor Author

@ti-srebot merge failed.

@crazycs520
Copy link
Contributor

/merge

@ti-srebot
Copy link
Contributor Author

/run-all-tests

@ti-srebot ti-srebot merged commit f0e90b1 into pingcap:release-4.0 Oct 19, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
epic/slow-query sig/execution SIG execution sig/sql-infra SIG: SQL Infra status/can-merge Indicates a PR has been approved by a committer. status/LGT3 The PR has already had 3 LGTM. type/4.0-cherry-pick
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants