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

crazycs520 · 2020-07-17T07:03:08Z

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.

Signed-off-by: crazycs520 <[email protected]>

…-collect-opt2

Signed-off-by: crazycs520 <[email protected]>

…-collect-txn-snapshot

Signed-off-by: crazycs520 <[email protected]>

codecov · 2020-07-17T10:55:06Z

Codecov Report

Merging #18666 into master will not change coverage.
The diff coverage is n/a.

@@             Coverage Diff             @@
##             master     #18666   +/-   ##
===========================================
  Coverage   79.3677%   79.3677%           
===========================================
  Files           544        544           
  Lines        148229     148229           
===========================================
  Hits         117646     117646           
  Misses        21192      21192           
  Partials       9391       9391

zz-jason · 2020-07-21T00:31:00Z

Get_rpc:{num:3, time:666.149µs},ResolveLock_rpc:{num:1, time:4.519421685s}

What does time mean, is it the average RPC time?

crazycs520 · 2020-07-21T06:58:07Z

@zz-jason

Get_rpc:{num:3, time:666.149µs},ResolveLock_rpc:{num:1, time:4.519421685s}

time means the total time that spent on xxx_RPC.
In the upper example, it means the Get_rpc total_count is 3, and total time is 666.149us.
the ResolveLock_rpc total_count is 1, and total time is 4.519421685s.

zz-jason · 2020-07-21T07:04:01Z

@zz-jason

Get_rpc:{num:3, time:666.149µs},ResolveLock_rpc:{num:1, time:4.519421685s}

time means the total time that spent on xxx_RPC.
In the upper example, it means the Get_rpc total_count is 3, and total time is 666.149us.
the ResolveLock_rpc total_count is 1, and total time is 4.519421685s.

How about:

Get{num_rpc:3, total_time:666.149us}, ResolveLock:{num_rpc:1, total_time:4.519421685s}

crazycs520 · 2020-07-21T07:08:58Z

@zz-jason

How about:

Get{num_rpc:3, total_time:666.149us}, ResolveLock:{num_rpc:1, total_time:4.519421685s}

Great, look good to me.

Signed-off-by: crazycs520 <[email protected]>

store/tikv/region_request.go

executor/point_get.go

qw4990

And also please add some tests for this. Integration tests like integration_test.go can be easily added for this case.

qw4990

LGTM

qw4990 · 2020-07-27T06:02:12Z

/merge

ti-srebot · 2020-07-27T06:02:14Z

@qw4990 Oops! This PR requires at least 2 LGTMs to merge. The current number of LGTM is 1.

lzmhhh123

@crazycs520 what about batch point-get executor?

crazycs520 · 2020-07-27T06:06:09Z

@lzmhhh123 I will add batch-point-get in the next PR, this PR is large enough.

lzmhhh123

LGTM

lzmhhh123 · 2020-07-27T06:07:25Z

/merge

ti-srebot · 2020-07-27T06:08:01Z

/run-all-tests

ti-srebot · 2020-07-27T06:11:31Z

@crazycs520 merge failed.

crazycs520 · 2020-07-27T06:12:07Z

/rebuild

crazycs520 · 2020-07-27T06:17:41Z

/build

crazycs520 · 2020-07-27T06:25:48Z

/rebuild

crazycs520 · 2020-07-27T07:10:31Z

/rebuild

crazycs520 · 2020-07-27T13:55:08Z

/run-unit-test
/run-check_dev_2

Signed-off-by: ti-srebot <[email protected]>

ti-srebot · 2020-07-28T06:21:44Z

cherry pick to release-4.0 in PR #18817

…8817)

crazycs520 added 7 commits July 10, 2020 22:01

refactor runtime stats

910c920

Signed-off-by: crazycs520 <[email protected]>

Merge branch 'master' of https://github.com/pingcap/tidb into runtime…

875c4ff

…-collect-opt2

init

2241b55

Signed-off-by: crazycs520 <[email protected]>

Merge branch 'master' of https://github.com/pingcap/tidb into runtime…

789073c

…-collect-txn-snapshot

fix test

76db517

Signed-off-by: crazycs520 <[email protected]>

refine code

6859e79

Signed-off-by: crazycs520 <[email protected]>

refine code

604c65c

Signed-off-by: crazycs520 <[email protected]>

crazycs520 added the sig/execution SIG execution label Jul 17, 2020

crazycs520 requested a review from a team as a code owner July 17, 2020 07:03

crazycs520 requested review from SunRunAway and removed request for a team July 17, 2020 07:03

add comment

1f3651b

Signed-off-by: crazycs520 <[email protected]>

crazycs520 mentioned this pull request Jul 17, 2020

improve the executor runtime information collection #18663

Open

25 tasks

Merge branch 'master' into runtime-collect-txn-snapshot

dd8c922

crazycs520 changed the title ~~executor: add executor runtime information for point-get~~ executor: add runtime information for point-get executor Jul 17, 2020

Merge branch 'master' into runtime-collect-txn-snapshot

0559fa8

Merge branch 'master' into runtime-collect-txn-snapshot

3e7cb14

qw4990 self-requested a review July 21, 2020 07:02

crazycs520 added 3 commits July 21, 2020 15:23

add comment

c33a90c

Signed-off-by: crazycs520 <[email protected]>

Merge branch 'master' into runtime-collect-txn-snapshot

6efb523

Merge branch 'master' into runtime-collect-txn-snapshot

d8de600

qw4990 reviewed Jul 21, 2020

View reviewed changes

store/tikv/region_request.go Show resolved Hide resolved

qw4990 reviewed Jul 21, 2020

View reviewed changes

executor/point_get.go Show resolved Hide resolved

qw4990 reviewed Jul 21, 2020

View reviewed changes

crazycs520 mentioned this pull request Jul 21, 2020

explain analyze support DML statement #18056

Closed

7 tasks

qw4990 approved these changes Jul 27, 2020

View reviewed changes

ti-srebot added the status/LGT1 Indicates that a PR has LGTM 1. label Jul 27, 2020

lzmhhh123 reviewed Jul 27, 2020

View reviewed changes

ti-srebot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Jul 27, 2020

ti-srebot approved these changes Jul 27, 2020

View reviewed changes

ti-srebot added the status/can-merge Indicates a PR has been approved by a committer. label Jul 27, 2020

crazycs520 added the needs-cherry-pick-4.0 label Jul 27, 2020

Merge branch 'master' into runtime-collect-txn-snapshot

76ecc34

Merge branch 'master' into runtime-collect-txn-snapshot

8389910

crazycs520 merged commit 8b19d67 into pingcap:master Jul 28, 2020

ti-srebot pushed a commit to ti-srebot/tidb that referenced this pull request Jul 28, 2020

cherry pick pingcap#18666 to release-4.0

1b13949

Signed-off-by: ti-srebot <[email protected]>

ti-srebot mentioned this pull request Jul 28, 2020

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

Merged

crazycs520 mentioned this pull request Jul 28, 2020

executor: add runtime information for the batch-point-get executor #18828

Merged

ti-srebot mentioned this pull request Jul 30, 2020

executor: add runtime information for the batch-point-get executor (#18828) #18892

Merged

SunRunAway pushed a commit that referenced this pull request Jul 31, 2020

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

9b26b78

…8817)

youjiali1995 mentioned this pull request Apr 27, 2021

Inaccurate runtime information for multi-region requests #24319

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

crazycs520 commented Jul 17, 2020 •

edited

Loading

codecov bot commented Jul 17, 2020 •

edited

Loading

zz-jason commented Jul 21, 2020

crazycs520 commented Jul 21, 2020 •

edited

Loading

zz-jason commented Jul 21, 2020

crazycs520 commented Jul 21, 2020

qw4990 left a comment

qw4990 left a comment

qw4990 commented Jul 27, 2020

ti-srebot commented Jul 27, 2020

lzmhhh123 left a comment

crazycs520 commented Jul 27, 2020

lzmhhh123 left a comment

lzmhhh123 commented Jul 27, 2020

ti-srebot commented Jul 27, 2020

ti-srebot commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

ti-srebot commented Jul 28, 2020

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

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

Conversation

crazycs520 commented Jul 17, 2020 • edited Loading

What problem does this PR solve?

Related changes

Check List

Release note

codecov bot commented Jul 17, 2020 • edited Loading

Codecov Report

zz-jason commented Jul 21, 2020

crazycs520 commented Jul 21, 2020 • edited Loading

zz-jason commented Jul 21, 2020

crazycs520 commented Jul 21, 2020

qw4990 left a comment

Choose a reason for hiding this comment

qw4990 left a comment

Choose a reason for hiding this comment

qw4990 commented Jul 27, 2020

ti-srebot commented Jul 27, 2020

lzmhhh123 left a comment

Choose a reason for hiding this comment

crazycs520 commented Jul 27, 2020

lzmhhh123 left a comment

Choose a reason for hiding this comment

lzmhhh123 commented Jul 27, 2020

ti-srebot commented Jul 27, 2020

ti-srebot commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

crazycs520 commented Jul 27, 2020

ti-srebot commented Jul 28, 2020

crazycs520 commented Jul 17, 2020 •

edited

Loading

codecov bot commented Jul 17, 2020 •

edited

Loading

crazycs520 commented Jul 21, 2020 •

edited

Loading