*: record execute runtime information in slow log #17573

crazycs520 · 2020-06-01T17:21:45Z

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

What problem does this PR solve?

Record execute runtime information in slow log plan, such as below:

Enable collect runtime execute information first:

set tidb_enable_collect_execution_info=1;

Then when TiDB output the slow-log, the Plan field value will like below, It will contain the plan runtime execute information.

# Plan: tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5NjQ4bRWEODc2CTEuOTA5NjAzMTE4OAEdDDQ0IE0JWxgyCTExXzEyAeHwWzAwMDAJdGFibGU6U0xPV19RVUVSWSwgb25seSBzZWFyY2ggaW4gdGhlIGN1cnJlbnQgJ3RpZGItc2xvdy5sb2cnIGZpbGUJNzY0NjkJdGltZTo2NTEuODk5NDAzHY4kNwlOL0EJTi9BCg==')

Decode the plan

test> select  tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5NjQ4bRWEODc2CTEuOTA5NjAzMTE4OAEdDDQ0IE0JWxgyCTExXzEyAeHwWzAwMDAJdGFibGU6U0xPV19RVUVSWSwgb25seSBzZWFyY2gga
   -> W4gdGhlIGN1cnJlbnQgJ3RpZGItc2xvdy5sb2cnIGZpbGUJNzY0NjkJdGltZTo2NTEuODk5NDAzHY4kNwlOL0EJTi9BCg==');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5Nj |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       HashAgg_8               root    1       funcs:count(1)->Column#50                                               1       time:766.09976ms, loops:2, PartialConcurrency:4, FinalConcurrency:4     10.740005493164062 MB   N/A                                                            |
|       └─Selection_11          root    8000    eq(Column#31, 0)                                                        76140   time:765.359648ms, loops:76                                             1.9096031188964844 MB   N/A                                                            |
|         └─MemTableScan_12     root    10000   table:SLOW_QUERY, only search in the current 'tidb-slow.log' file       76469   time:651.899403ms, loops:77                                             N/A                     N/A                                                            |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

As you see, the execute information was contain in the slow-log Plan field now. Since the decode plan field was become too many, we had better add some header column name to more readable, such as below, but we can do this in next PR:

test> select  tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5NjQ4bRWEODc2CTEuOTA5NjAzMTE4OAEdDDQ0IE0JWxgyCTExXzEyAeHwWzAwMDAJdGFibGU6U0xPV19RVUVSWSwgb25seSBzZWFyY2ggaW4gdGhlIGN1cnJlbnQgJ3RpZGItc2xvdy5sb2cnIGZpbGUJNzY0NjkJdGltZ
   -> To2NTEuODk5NDAzHY4kNwlOL0EJTi9BCg==');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('2wLwlTAJNl84CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzUwCTEJdGltZTo3NjYuMDk5NzZtcywgbG9vcHM6MiwgUGFydGlhbENvbmN1cnJlbmN5OjQsIEZpbmFsQ29uY3VycmVuY3k6NAkxMC43NDAwMDU0OTMxNjQwNjIgTUIJTi9BCjEJMV8xMQkwCTgwMDAJZXEoQwl7LDMxLCAwKQk3NjE0MBGDIDUuMzU5Nj |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       id                      task    estRows operator info                                                           actRows execution info                                                          memory                  disk                                                       |
|       HashAgg_8               root    1       funcs:count(1)->Column#50                                               1       time:766.09976ms, loops:2, PartialConcurrency:4, FinalConcurrency:4     10.740005493164062 MB   N/A                                                        |
|       └─Selection_11          root    8000    eq(Column#31, 0)                                                        76140   time:765.359648ms, loops:76                                             1.9096031188964844 MB   N/A                                                        |
|         └─MemTableScan_12     root    10000   table:SLOW_QUERY, only search in the current 'tidb-slow.log' file       76469   time:651.899403ms, loops:77                                             N/A                     N/A                                                        |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

What is changed and how it works?

Related changes

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

Check List

Tests

Unit test(ing)
Manual test (add detailed scripts or steps below)

Side effects

Performance regression
- Consumes more CPU
- Consumes more MEM

Release note

record execute runtime information in slow log.

Signed-off-by: crazycs <crazycs520@gmail.com>

sre-bot · 2020-06-01T17:22:00Z

No release note, Please follow https://github.com/pingcap/community/blob/master/contributors/release-note-checker.md

Signed-off-by: crazycs <crazycs520@gmail.com>

… into slow-log-plan-info

Signed-off-by: crazycs <crazycs520@gmail.com>

qw4990

LGTM!

qw4990 · 2020-06-02T03:25:51Z

/run-all-tests

crazycs520 · 2020-06-02T06:15:51Z

/run-all-tests

codecov · 2020-06-02T11:08:22Z

Codecov Report

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

@@             Coverage Diff             @@
##             master     #17573   +/-   ##
===========================================
  Coverage   79.4174%   79.4174%           
===========================================
  Files           520        520           
  Lines        139973     139973           
===========================================
  Hits         111163     111163           
  Misses        19819      19819           
  Partials       8991       8991

wjhuang2016 · 2020-06-02T11:28:03Z

planner/core/common_plans.go

+		analyzeInfo = "time:0ns, loops:0"
+	}
+	switch p.(type) {
+	case *PhysicalTableReader, *PhysicalIndexReader, *PhysicalIndexLookUpReader:


how about PhysicalIndexMergeReader?

I just extract those code from prepareOperatorInfo, I'm not sure whether it is a bug.... @qw4990 PTAL

We can ignore this problem here since it's another thing, the PhysicalIndexMergeReader doesn't support collecting read-stats now. @wjhuang2016 @crazycs520

Signed-off-by: crazycs <crazycs520@gmail.com>

zz-jason · 2020-06-02T16:03:00Z

What's the performance impact when we enable this by default?

wjhuang2016

LGTM

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

sre-bot · 2020-06-09T03:23:03Z

Sorry @wjhuang2016, you don't have permission to trigger auto merge event on this branch. You are not a committer for this part

crazycs520 · 2020-06-09T03:33:23Z

/run-all-tests

crazycs520 · 2020-06-09T03:39:01Z

/run-all-tests

crazycs520 · 2020-06-09T03:42:56Z

/run-integration-ddl-test

crazycs520 · 2020-06-17T07:01:09Z

/run-cherry-picker

Signed-off-by: ti-srebot <ti-srebot@pingcap.com>

ti-srebot · 2020-06-17T07:02:56Z

cherry pick to release-4.0 in PR #18072

init

9840c53

Signed-off-by: crazycs <crazycs520@gmail.com>

crazycs520 added the type/enhancement The issue or PR belongs to an enhancement. label Jun 1, 2020

github-actions bot added the sig/planner SIG: Planner label Jun 1, 2020

crazycs520 added 6 commits June 2, 2020 08:56

Merge branch 'master' into slow-log-plan-info

cec70da

fix test

cb3b2dd

Signed-off-by: crazycs <crazycs520@gmail.com>

Merge branch 'slow-log-plan-info' of https://github.com/crazycs520/tidb…

1f993f5

… into slow-log-plan-info

add test1

1a7b7bc

Signed-off-by: crazycs <crazycs520@gmail.com>

add test2

5ca3ee8

Signed-off-by: crazycs <crazycs520@gmail.com>

fix panic

90121f8

Signed-off-by: crazycs <crazycs520@gmail.com>

github-actions bot added the component/expression label Jun 2, 2020

crazycs520 added 2 commits June 2, 2020 10:49

make test stable

73b1026

Signed-off-by: crazycs <crazycs520@gmail.com>

Merge branch 'master' into slow-log-plan-info

0fc0940

qw4990 self-requested a review June 2, 2020 02:54

qw4990 mentioned this pull request Jun 2, 2020

Add more information in slow logs to help analyze slow queries #17557

Closed

10 tasks

qw4990 reviewed Jun 2, 2020

View reviewed changes

qw4990 requested a review from Reminiscent June 2, 2020 03:36

crazycs520 added 2 commits June 2, 2020 16:48

Merge branch 'master' into slow-log-plan-info

aef298f

Merge branch 'master' into slow-log-plan-info

fd5aa68

wjhuang2016 reviewed Jun 2, 2020

View reviewed changes

crazycs520 added 4 commits June 2, 2020 22:58

try to fix test

cd1601b

Signed-off-by: crazycs <crazycs520@gmail.com>

try to fix test race

d7dd02f

Signed-off-by: crazycs <crazycs520@gmail.com>

Merge branch 'master' into slow-log-plan-info

8c86eaf

Merge branch 'master' into slow-log-plan-info

5b90223

zz-jason requested review from SunRunAway and XuHuaiyu June 2, 2020 16:03

wjhuang2016 reviewed Jun 8, 2020

View reviewed changes

qw4990 and others added 4 commits June 8, 2020 16:37

Merge branch 'master' into slow-log-plan-info

de40722

close collect runtime information by default

be4b51b

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

Merge branch 'master' into slow-log-plan-info

e758b5c

fix test

d4a86d6

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

wjhuang2016 approved these changes Jun 9, 2020

View reviewed changes

wjhuang2016 added status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2. labels Jun 9, 2020

crazycs520 merged commit 36ea109 into pingcap:master Jun 9, 2020

crazycs520 deleted the slow-log-plan-info branch June 15, 2020 06:56

crazycs520 added the needs-cherry-pick-4.0 label Jun 17, 2020

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

cherry pick pingcap#17573 to release-4.0

fd7aad8

Signed-off-by: ti-srebot <ti-srebot@pingcap.com>

ti-srebot mentioned this pull request Jun 17, 2020

*: record execute runtime information in slow log (#17573) #18072

Merged

crazycs520 pushed a commit that referenced this pull request Jun 18, 2020

*: record execute runtime information in slow log (#17573) (#18072)

ab8648e

crazycs520 mentioned this pull request Jun 24, 2020

*: add more doc for slow log pingcap/docs-cn#3791

Merged

5 tasks

This was referenced Jul 7, 2020

config: enable collect execution information by default #18415

Merged

expression: add header for tidb_decode_plan result #18440

Merged

This was referenced Jul 13, 2020

expression: add header for tidb_decode_plan result (#18440) #18501

Merged

config: enable collect execution information by default (#18415) #18518

Merged

crazycs520 mentioned this pull request Jul 17, 2020

explain analyze support DML statement #18056

Closed

7 tasks

breezewish mentioned this pull request Aug 3, 2020

Enable tidb_enable_collect_execution_info by default? #18937

Closed

ti-srebot mentioned this pull request Sep 10, 2020

*: add more doc for slow log (#3791) pingcap/docs-cn#4468

Merged

5 tasks

qw4990 mentioned this pull request Sep 23, 2020

update docs about logs pingcap/docs-cn#4575

Merged

5 tasks

ti-srebot mentioned this pull request Nov 2, 2020

update docs about logs (#4575) pingcap/docs-cn#4773

Merged

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: record execute runtime information in slow log #17573

*: record execute runtime information in slow log #17573

crazycs520 commented Jun 1, 2020 •

edited

Loading

sre-bot commented Jun 1, 2020

qw4990 left a comment

qw4990 commented Jun 2, 2020

crazycs520 commented Jun 2, 2020

codecov bot commented Jun 2, 2020 •

edited

Loading

wjhuang2016 Jun 2, 2020

crazycs520 Jun 2, 2020

qw4990 Jun 8, 2020

zz-jason commented Jun 2, 2020

wjhuang2016 left a comment

sre-bot commented Jun 9, 2020

crazycs520 commented Jun 9, 2020

crazycs520 commented Jun 9, 2020

crazycs520 commented Jun 9, 2020

crazycs520 commented Jun 17, 2020

ti-srebot commented Jun 17, 2020

*: record execute runtime information in slow log #17573

*: record execute runtime information in slow log #17573

Conversation

crazycs520 commented Jun 1, 2020 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Related changes

Check List

Release note

sre-bot commented Jun 1, 2020

qw4990 left a comment

Choose a reason for hiding this comment

qw4990 commented Jun 2, 2020

crazycs520 commented Jun 2, 2020

codecov bot commented Jun 2, 2020 • edited Loading

Codecov Report

wjhuang2016 Jun 2, 2020

Choose a reason for hiding this comment

crazycs520 Jun 2, 2020

Choose a reason for hiding this comment

qw4990 Jun 8, 2020

Choose a reason for hiding this comment

zz-jason commented Jun 2, 2020

wjhuang2016 left a comment

Choose a reason for hiding this comment

sre-bot commented Jun 9, 2020

crazycs520 commented Jun 9, 2020

crazycs520 commented Jun 9, 2020

crazycs520 commented Jun 9, 2020

crazycs520 commented Jun 17, 2020

ti-srebot commented Jun 17, 2020

crazycs520 commented Jun 1, 2020 •

edited

Loading

codecov bot commented Jun 2, 2020 •

edited

Loading