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

[ti-srebot]

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.

[ti-srebot]

/run-all-tests

[AilinKid]

LGTM

[crazycs520]

/run-all-tests

[qw4990]

LGTM

[crazycs520]

/run-all-tests

[crazycs520]

/merge

[ti-srebot]

/run-all-tests

[ti-srebot]

@ti-srebot merge failed.

[tangenta]

LGTM

[crazycs520]

/merge

[ti-srebot]

/run-all-tests

[ti-srebot]

@ti-srebot merge failed.

[crazycs520]

/merge

[ti-srebot]

/run-all-tests