executor: add runtime information for point-get executor (#18666)

[ti-srebot]

cherry-pick #18666 to release-4.0

---

What problem does this PR solve?

As the title said.

Here is some example of explain analyze select * from t where a=1;

Normally

+-------------+---------+---------+------+------------------------+----------------------------------------------------------+---------------+--------+------+
| id          | estRows | actRows | task | access object          | execution info                                           | operator info | memory | disk |
+-------------+---------+---------+------+------------------------+----------------------------------------------------------+---------------+--------+------+
| Point_Get_1 | 1.00    | 1       | root | table:t, index:idx1(a) | time:699.459µs, loops:2, Get_rpc:{num:2, time:662.459µs} |               | N/A    | N/A  |
+-------------+---------+---------+------+------------------------+----------------------------------------------------------+---------------+--------+------+

when point-get meet lock:

+-------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------+---------------+--------+------+
| id          | estRows | actRows | task | access object          | execution info                                                                                                                                    | operator info | memory | disk |
+-------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------+---------------+--------+------+
| Point_Get_1 | 1.00    | 1       | root | table:t, index:idx1(a) | time:4.520115944s, loops:2, Get_rpc:{num:3, time:666.149µs},ResolveLock_rpc:{num:1, time:4.519421685s},txnNotFound_backoff:{num:16, time:4510 ms} |               | N/A    | N/A  |
+-------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------+---------------+--------+------+

when tikv restart:

+-------------+---------+---------+------+------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------+---------------+--------+------+
| id          | estRows | actRows | task | access object          | execution info                                                                                                                                  | operator info | memory | disk |
+-------------+---------+---------+------+------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------+---------------+--------+------+
| Point_Get_1 | 1.00    | 1       | root | table:t, index:idx1(a) | time:9.051671089s, loops:2, Get_rpc:{num:11, time:8.020006147s},tikvRPC_backoff:{num:9, time:7998 ms},regionMiss_backoff:{num:10, time:1012 ms} |               | N/A    | N/A  |
+-------------+---------+---------+------+------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------+---------------+--------+------+

Of course, the slow-log will also record the point-get runtime information too:

select plan from information_schema.`SLOW_QUERY` where time > "2020-07-17 14:20:00" and query like "select% t%" order by query_time desc limit 1\G
***************************[ 1. row ]***************************
plan |  id              task    estRows operator info           actRows execution info                                                                                                                                  memory  disk
        Point_Get_1     root    1       table:t, index:idx1(a)  1       time:5.233083269s, loops:2, Get_rpc:{num:9, time:4.957755414s},regionMiss_backoff:{num:8, time:256 ms},tikvRPC_backoff:{num:7, time:4944 ms}    N/A     N/A

Related changes

• Need to cherry-pick to the release branch

Check List

Tests

• Manual test (add detailed scripts or steps below)

Side effects

• Performance regression
  • Consumes more CPU

Release note

• Add executor runtime information for point-get.

[ti-srebot]

/run-all-tests

[crazycs520]

/run-all-tests

[crazycs520]

/run-all-tests

[qw4990]

LGTM

[qw4990]

/run-all-tests

[SunRunAway]

LGTM

[SunRunAway]

/merge

[ti-srebot]

/run-all-tests

[ti-srebot]

@ti-srebot merge failed.