*: add max/avg cop response time for TableReader, IndexReader and IndexLookupReader. #12003

lzmhhh123 · 2019-09-03T07:51:13Z

What problem does this PR solve?

When explain analyze only shows the running time in coprocessor, but it doesn't consider the network trans time, encode time in coprocessor and decode time in tidb. So this PR adds a max coprocessor response time to fetch more information.

tidb(localhost:4000) > desc analyze select /*+ TIDB_INLJ(t, s) */ t.a from t left join s on t.a = s.a order by t.a desc;
+--------------------------+-------+------+----------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------+----------------+
| id                       | count | task | operator info                                                                                | execution info                                                                                                                 | memory         |
+--------------------------+-------+------+----------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------+----------------+
| Projection_16            | 3.75  | root | test.t.a                                                                                     | time:778.424µs, loops:2, rows:5                                                                                                | N/A            |
| └─IndexJoin_21           | 3.75  | root | left outer join, inner:IndexReader_20, outer key:test.t.a, inner key:test.s.a                | time:776.036µs, loops:2, rows:5                                                                                                | 21.19140625 KB |
|   ├─IndexReader_23       | 3.00  | root | index:IndexScan_22                                                                           | time:18.45µs, loops:3, rows:3, cop resp time max:213.883µs, min:213.883µs, avg:213.883µs, p80:213.883µs, p95:213.883µs         | 155 Bytes      |
|   │ └─IndexScan_22       | 3.00  | cop  | table:t, index:a, range:[NULL,+inf], keep order:true, desc                                   | time:131.697µs, loops:4, rows:3                                                                                                | N/A            |
|   └─IndexReader_20       | 0.01  | root | index:Selection_19                                                                           | time:312.121µs, loops:2, rows:4, cop resp time max:248.136µs, min:248.136µs, avg:248.136µs, p80:248.136µs, p95:248.136µs       | 190 Bytes      |
|     └─Selection_19       | 0.01  | cop  | not(isnull(test.s.a))                                                                        | time:107.07µs, loops:5, rows:4                                                                                                 | N/A            |
|       └─IndexScan_18     | 0.01  | cop  | table:s, index:a, range: decided by [eq(test.s.a, test.t.a)], keep order:false, stats:pseudo | time:95.173µs, loops:5, rows:4                                                                                                 | N/A            |
+--------------------------+-------+------+----------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------+----------------+
7 rows in set (0.02 sec)

Check List

Tests

Unit test
Integration test

Code changes

Has exported function/method change
Has exported variable/fields change
Has interface methods change
Has persistent data change

Side effects

Possible performance regression
Increased code complexity

distsql/select_result.go

…tidb into dev/add_cop_resp_time

SunRunAway

The execution format in Cop task is proc max:%v, min:%v, p80:%v, p95:%v, rows:%v, iters:%v, tasks:%v
Could you unify them?

lzmhhh123 · 2019-09-04T11:10:37Z

/run-unit-test

codecov · 2019-09-04T11:30:56Z

Codecov Report

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

@@             Coverage Diff             @@
##             master     #12003   +/-   ##
===========================================
  Coverage   81.3524%   81.3524%           
===========================================
  Files           453        453           
  Lines         97450      97450           
===========================================
  Hits          79278      79278           
  Misses        12510      12510           
  Partials       5662       5662

lzmhhh123 · 2019-09-06T09:11:02Z

/run-all-tests

zz-jason · 2019-09-04T09:11:44Z

util/execdetails/execdetails.go

+}
+
+// RecordOneCopTask record once cop response time to update maxCopRespTime
+func (rrs *ReaderRuntimeStats) RecordOneCopTask(t time.Duration) {


no need to export this function.

zz-jason · 2019-09-10T11:15:49Z

util/execdetails/execdetails.go

+	defer e.mu.Unlock()
+	stats, exists := e.readerStats[planID]
+	if !exists {
+		stats = &ReaderRuntimeStats{copRespTime: make([]time.Duration, 0, 20)}


Just curious, why setting the slice capacity to 20?

Just a casual value.

Do you have any idea or just set it zero.

util/execdetails/execdetails.go

eurekaka · 2019-09-11T03:28:12Z

planner/core/common_plans.go

 		}
+		switch p.(type) {
+		case *PhysicalTableReader, *PhysicalIndexReader, *PhysicalIndexLookUpReader:
+			if runtimeStatsColl.GetReaderStats(explainID) != nil {


Suggested change

if runtimeStatsColl.GetReaderStats(explainID) != nil {

if s := runtimeStatsColl.GetReaderStats(explainID); s != nil {

eurekaka · 2019-09-11T03:28:25Z

planner/core/common_plans.go

+		switch p.(type) {
+		case *PhysicalTableReader, *PhysicalIndexReader, *PhysicalIndexLookUpReader:
+			if runtimeStatsColl.GetReaderStats(explainID) != nil {
+				analyzeInfo += ", " + runtimeStatsColl.GetReaderStats(explainID).String()


Suggested change

analyzeInfo += ", " + runtimeStatsColl.GetReaderStats(explainID).String()

analyzeInfo += ", " + s.String()

disksing · 2019-09-11T03:38:05Z

em, no proc time any more?

disksing · 2019-09-11T03:40:17Z

util/execdetails/execdetails.go

+	sort.Slice(rrs.copRespTime, func(i, j int) bool {
+		return rrs.copRespTime[i] < rrs.copRespTime[j]
+	})
+	s := "cop resp time "


Can we make it shorter? How about the same form as proc time and call it rpc time?

lzmhhh123 · 2019-09-11T03:42:45Z

em, no proc time any more?

In mocktikv. It doesn't have proc time.
In tikv or tiflash, it has.

tidb(localhost:4000) > desc analyze select /*+ read_from_storage(tiflash[lineitem]) */ * from lineitem;
+-------------------+------------+--------------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------+-----$-----------------+
| id                | count      | task         | operator info                                       | execution info                                                                                                                                           | memo$y                |
+-------------------+------------+--------------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------+-----$-----------------+
| TableReader_5     | 6001215.00 | root         | data:TableScan_4                                    | time:50.560209007s, loops:5862, rows:6001215, cop resp time max:23.160214791s, min:3.868990591s, avg:10.995373571s, p80:22.553894442s, p95:22.684954285s | 163.83687496185303 MB |
| └─TableScan_4     | 6001215.00 | cop[tiflash] | table:lineitem, range:[-inf,+inf], keep order:false | proc max:1.176744s, min:382.01ms, p80:1.03543s, p95:1.093618s, rows:6001215, iters:796, tasks:63                                                         | N/A                 |
+-------------------+------------+--------------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+
2 rows in set (50.81 sec)

eurekaka

LGTM

util/execdetails/execdetails.go

qw4990

LGTM

zz-jason

LGTM

sre-bot · 2019-09-11T09:01:59Z

Your auto merge job has been accepted, waiting for 12009, 12085

lzmhhh123 · 2019-09-11T09:49:48Z

@zz-jason Prev auto-merge job caused conflicts. The approvement is dismissed by merge master.

lzmhhh123 · 2019-09-11T12:28:32Z

/merge

sre-bot · 2019-09-11T12:30:47Z

/run-all-tests

…exLookupReader. (pingcap#12003)

lzmhhh123 added 2 commits September 3, 2019 15:43

add max cop resp time

7395371

fix

15f5d3d

lzmhhh123 added the type/usability label Sep 3, 2019

lzmhhh123 added 2 commits September 3, 2019 15:54

fix ci

d741b04

add avg

1dc762c

lzmhhh123 changed the title *: add max cop response time for TableReader, IndexReader and IndexLookupReader. *: add max/avg cop response time for TableReader, IndexReader and IndexLookupReader. Sep 3, 2019

lzmhhh123 added 2 commits September 3, 2019 19:23

Merge remote-tracking branch 'origin/master' into dev/add_cop_resp_time

a7ba0d7

Merge branch 'master' into dev/add_cop_resp_time

742f903

qw4990 self-requested a review September 4, 2019 05:05

qw4990 reviewed Sep 4, 2019

View reviewed changes

distsql/select_result.go Outdated Show resolved Hide resolved

fix error

2cd3540

lzmhhh123 requested review from SunRunAway, zz-jason and eurekaka September 4, 2019 05:47

Merge branch 'dev/add_cop_resp_time' of https://github.com/lzmhhh123/…

0fc03c5

…tidb into dev/add_cop_resp_time

SunRunAway reviewed Sep 4, 2019

View reviewed changes

fix and improve

3d8e83c

XuHuaiyu self-requested a review September 4, 2019 09:39

lzmhhh123 requested a review from SunRunAway September 4, 2019 09:59

Merge branch 'master' into dev/add_cop_resp_time

f285240

lzmhhh123 added 4 commits September 6, 2019 08:29

Merge branch 'master' into dev/add_cop_resp_time

9523d48

Merge branch 'master' into dev/add_cop_resp_time

1bfd10f

fix data race

bd9c53b

fix ci

cb0851f

lzmhhh123 added the status/all tests passed label Sep 6, 2019

zz-jason reviewed Sep 10, 2019

View reviewed changes

zz-jason mentioned this pull request Sep 11, 2019

Show coprocessor request duration in explain analyze #12148

Closed

eurekaka reviewed Sep 11, 2019

View reviewed changes

disksing reviewed Sep 11, 2019

View reviewed changes

address comments

8299c98

lzmhhh123 requested review from qw4990 and eurekaka September 11, 2019 05:04

eurekaka reviewed Sep 11, 2019

View reviewed changes

remove min/avg when only one cop task

c3185d0

zz-jason reviewed Sep 11, 2019

View reviewed changes

util/execdetails/execdetails.go Outdated Show resolved Hide resolved

address comments

0dab646

qw4990 reviewed Sep 11, 2019

View reviewed changes

zz-jason previously approved these changes Sep 11, 2019

View reviewed changes

zz-jason added status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2. labels Sep 11, 2019

Merge branch 'master' into dev/add_cop_resp_time

4021e76

lzmhhh123 dismissed zz-jason’s stale review via 4021e76 September 11, 2019 09:47

zz-jason approved these changes Sep 11, 2019

View reviewed changes

Merge branch 'master' into dev/add_cop_resp_time

7fab8ab

sre-bot merged commit 39e9c9f into pingcap:master Sep 11, 2019

lzmhhh123 deleted the dev/add_cop_resp_time branch September 11, 2019 12:37

lzmhhh123 added a commit to lzmhhh123/tidb that referenced this pull request Jan 19, 2020

*: add max/avg cop response time for TableReader, IndexReader and Ind…

c32ba61

…exLookupReader. (pingcap#12003)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: add max/avg cop response time for TableReader, IndexReader and IndexLookupReader. #12003

*: add max/avg cop response time for TableReader, IndexReader and IndexLookupReader. #12003

lzmhhh123 commented Sep 3, 2019 •

edited by zz-jason

Loading

SunRunAway left a comment

lzmhhh123 commented Sep 4, 2019

codecov bot commented Sep 4, 2019 •

edited

Loading

lzmhhh123 commented Sep 6, 2019

zz-jason Sep 4, 2019

zz-jason Sep 10, 2019

lzmhhh123 Sep 11, 2019

lzmhhh123 Sep 11, 2019

eurekaka Sep 11, 2019

eurekaka Sep 11, 2019

disksing commented Sep 11, 2019

disksing Sep 11, 2019

lzmhhh123 Sep 11, 2019

lzmhhh123 commented Sep 11, 2019

eurekaka left a comment

qw4990 left a comment

zz-jason left a comment

sre-bot commented Sep 11, 2019

lzmhhh123 commented Sep 11, 2019

lzmhhh123 commented Sep 11, 2019

sre-bot commented Sep 11, 2019

	if runtimeStatsColl.GetReaderStats(explainID) != nil {
	if s := runtimeStatsColl.GetReaderStats(explainID); s != nil {

	analyzeInfo += ", " + runtimeStatsColl.GetReaderStats(explainID).String()
	analyzeInfo += ", " + s.String()

*: add max/avg cop response time for TableReader, IndexReader and IndexLookupReader. #12003

*: add max/avg cop response time for TableReader, IndexReader and IndexLookupReader. #12003

Conversation

lzmhhh123 commented Sep 3, 2019 • edited by zz-jason Loading

What problem does this PR solve?

Check List

SunRunAway left a comment

Choose a reason for hiding this comment

lzmhhh123 commented Sep 4, 2019

codecov bot commented Sep 4, 2019 • edited Loading

Codecov Report

lzmhhh123 commented Sep 6, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

disksing commented Sep 11, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lzmhhh123 commented Sep 11, 2019

eurekaka left a comment

Choose a reason for hiding this comment

qw4990 left a comment

Choose a reason for hiding this comment

zz-jason left a comment

Choose a reason for hiding this comment

sre-bot commented Sep 11, 2019

lzmhhh123 commented Sep 11, 2019

lzmhhh123 commented Sep 11, 2019

sre-bot commented Sep 11, 2019

lzmhhh123 commented Sep 3, 2019 •

edited by zz-jason

Loading

codecov bot commented Sep 4, 2019 •

edited

Loading