Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

*: record and print the plan in slow log. (#12179) #13297

Merged
merged 3 commits into from
Nov 11, 2019
Merged

*: record and print the plan in slow log. (#12179) #13297

merged 3 commits into from
Nov 11, 2019

Conversation

bb7133
Copy link
Member

@bb7133 bb7133 commented Nov 8, 2019

What problem does this PR solve?

Backport #12179 by cherry-picking #12808

Conflict files(from #12808):

        both modified:   executor/adapter.go
        both modified:   planner/core/common_plans.go
        both modified:   sessionctx/variable/session.go

Related Parser PR: pingcap/parser#629

What problem does this PR solve?

  1. Print the plan in slow log.
  2. Add slow-log-plan config item and system variable to control enable.
  3. Add plan encode and plan decoder function.
  4. Add tidb_decode_plan function to decode the ecoded plan string.
  5. Add Plan column to Slow_query table.

Related PR: pingcap/parser#557

Example

Enable tidb_record_plan_in_slow_log first.

set @@tidb_record_plan_in_slow_log=1;
select count(*) from t1  join t1 t2 where t1.a=t2.b union select count(*) from t1  join t1 t2 where t1.a=t2.b union select count(*) from t1  join t1 t2 where t1.a=t2.b union select sleep(1);

In slow log

As is seen, Plan is the string of the encoded query plan.

# Time: 2019-09-12T19:36:50.003062+08:00
# Txn_start_ts: 411117344255639553
# User: root@127.0.0.1
# Conn_ID: 1
# Query_time: 1.002325096
# Request_count: 6 Total_keys: 36 Process_keys: 30
# DB: test
# Index_names: [t1:a,t1:b,t1:a,t1:b,t1:a,t1:b]
# Is_internal: false
# Digest: 35476665610eec1a5dff15ef68287edc48fa6b924d650f8dc26c4754b2293322
# Stats: t1:pseudo
# Num_cop_tasks: 6
# Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr: 127.0.0.1:20164
# Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr: 127.0.0.1:20164
# Mem_max: 2232
# Succ: true
# Plan: tidb_decode_plan('eNq0lM1uqzAQRtfDU3iZ3EsRY2MT+w267rKqLCAmpYkMso3SvH3FnxpVIouKbljMN8xhjkakIDSjkEIGJ9f2HSlvqmp7G3b/9jGpe1t5VTfOB9ded0uwjxCkZmx8LaLANMsgBYSq8OGuiwHXTI7JNGmKcB9lgFKLIRIJzVjOobHWOPLRNjYmF1MHcjY3FYwPScCkiIlrTu/3RZqUEQdGtRi/PpFymHE0n+p5eL5UhdUCIwHItEDAuSUU5cWogDGZmofJhT0Z9frU2Dr+39j6LSZnYzrSuqNxKrjexMSHInjVedMf2xmbrWPZjGU/sXTBlr/ADp5luuZZ8lXPSPkWohEPqysj5tPOiPn2rpGmD8hyIcvNdWMm1nwjx3XhB9xEeL5+Y5jPR4Y5+wPhuXhA5guZby6cpvRb+CB6KLGx5C/GdJNiyjVNpz+Oa69eYfQVAAD//z6BX5c=')
select count(*) from t1  join t1 t2 where t1.a=t2.b union select count(*) from t1  join t1 t2 where t1.a=t2.b union select count(*) from t1  join t1 t2 where t1.a=t2.b union select sleep(1);

query the slow_query table

mysql>select plan,query from slow_query where plan != "" order by query_time  limit 1;
+-------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| plan                                                                                                        | query                                                                                                                                                                                          |
+-------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       HashAgg_32                      root    4       group by:Column#32, funcs:firstrow(Column#32)                      | select count(*) from t1  join t1 t2 where t1.a=t2.b union select count(*) from t1  join t1 t2 where t1.a=t2.b union select count(*) from t1  join t1 t2 where t1.a=t2.b union select sleep(1); |
|       └─Union_33                      root    4                                                                          |                                                                                                                                                                                                |
|         ├─Projection_34               root    1       cast(Column#30)                                                    |                                                                                                                                                                                                |
|         │ └─HashAgg_37                root    1       funcs:count(1)                                                     |                                                                                                                                                                                                |
|         │   └─HashLeftJoin_40         root    12487.5 inner join, inner:TableReader_47, equal:[eq(Column#22, Column#27)] |                                                                                                                                                                                                |
|         │     ├─TableReader_44        root    9990    data:Selection_43                                                  |                                                                                                                                                                                                |
|         │     │ └─Selection_43        cop     9990    not(isnull(Column#22))                                             |                                                                                                                                                                                                |
|         │     │   └─TableScan_42      cop     10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo        |                                                                                                                                                                                                |
|         │     └─TableReader_47        root    9990    data:Selection_46                                                  |                                                                                                                                                                                                |
|         │       └─Selection_46        cop     9990    not(isnull(Column#27))                                             |                                                                                                                                                                                                |
|         │         └─TableScan_45      cop     10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo        |                                                                                                                                                                                                |
|         ├─Projection_50               root    1       cast(Column#20)                                                    |                                                                                                                                                                                                |
|         │ └─HashAgg_53                root    1       funcs:count(1)                                                     |                                                                                                                                                                                                |
|         │   └─HashLeftJoin_56         root    12487.5 inner join, inner:TableReader_63, equal:[eq(Column#12, Column#17)] |                                                                                                                                                                                                |
|         │     ├─TableReader_60        root    9990    data:Selection_59                                                  |                                                                                                                                                                                                |
|         │     │ └─Selection_59        cop     9990    not(isnull(Column#12))                                             |                                                                                                                                                                                                |
|         │     │   └─TableScan_58      cop     10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo        |                                                                                                                                                                                                |
|         │     └─TableReader_63        root    9990    data:Selection_62                                                  |                                                                                                                                                                                                |
|         │       └─Selection_62        cop     9990    not(isnull(Column#17))                                             |                                                                                                                                                                                                |
|         │         └─TableScan_61      cop     10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo        |                                                                                                                                                                                                |
|         ├─Projection_66               root    1       cast(Column#10)                                                    |                                                                                                                                                                                                |
|         │ └─HashAgg_69                root    1       funcs:count(1)                                                     |                                                                                                                                                                                                |
|         │   └─HashLeftJoin_72         root    12487.5 inner join, inner:TableReader_79, equal:[eq(Column#2, Column#7)]   |                                                                                                                                                                                                |
|         │     ├─TableReader_76        root    9990    data:Selection_75                                                  |                                                                                                                                                                                                |
|         │     │ └─Selection_75        cop     9990    not(isnull(Column#2))                                              |                                                                                                                                                                                                |
|         │     │   └─TableScan_74      cop     10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo        |                                                                                                                                                                                                |
|         │     └─TableReader_79        root    9990    data:Selection_78                                                  |                                                                                                                                                                                                |
|         │       └─Selection_78        cop     9990    not(isnull(Column#7))                                              |                                                                                                                                                                                                |
|         │         └─TableScan_77      cop     10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo        |                                                                                                                                                                                                |
|         └─Projection_82               root    1       cast(Column#1)                                                     |                                                                                                                                                                                                |
|           └─Projection_83             root    1       sleep(1)                                                           |                                                                                                                                                                                                |
|             └─TableDual_84            root    1       rows:1                                                             |                                                                                                                                                                                                |
+-------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Use tidb_decode_plan function to decode the encoded plan string.

mysql>select tidb_decode_plan('jAu4MAk2XzMyCTAJNAlncm91cCBieTpDb2x1bW4jMzIsIGZ1bmNzOmZpcnN0cm93KEMRGhwpCjEJOV8zMwU5PAoyCTNfMzQJMAkxCWNhc3QVJwwwKQozAWAANwUbCUw8Y291bnQoMSkKNAkxN180MAEbSDI0ODcuNQlpbm5lciBqb2luLCAFDGQ6VGFibGVSZWFkZXJfNDcsIGVxdWFsOltlcRFjDDIyLCANrygyNyldCjUJMzJfNAGLeDk5OTAJZGF0YTpTZWxlY3Rpb25fNDMKNgkxXzQzCTEJICRub3QoaXNudWxsGVFMKSkKNwkxMF80MgkxCTEwMDAwCXQBh9g6dDEsIHJhbmdlOlstaW5mLCtpbmZdLCBrZWVwIG9yZGVyOmZhbHNlLCBzdGF0czpwc2V1ZG8KCZIhAlKSAAA2CZIANmqSAAA3FZIANT6SAAAyzpIAIa4ANSV4Mq4BADItrgA1IdUAMVKuAQQ1NqKuAQQ2M0quAQAxOa4AMTWuADYBi04cAQQ1OSUcCDU5CWKuAQAxNa4ENTg+HAHmrgEANiECTpIABDYyBZIANkEaBSBGQAIAMTWuBDYxPpIA4q4BADYleDKuAQAxLa4ENjkhk1KuAQA3YdeWXAMENzlKrgE5rTWsADcBiQX6OloDCDc1CmFaADdBogUgRhoBNasENzQ+GQHmqwEANwH/BXE+kQAAOAmRQRcFIEaRADWqBDc3PpEA4qoBADgldDaqAaEFCDNfOEFVGDEJc2xlZXCJ/0AyNl84NAkwCTEJcm93czoxCg==');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('jAu4MAk2XzMyCTAJNAlncm91cCBieTpDb2x1bW4jMzIsIGZ1bmNzOmZpcnN0cm93KEMRGhwpCjEJOV8zMwU5PAoyCTNfMzQJMAkxCWNhc3QVJwwwKQozAWAANwUbCUw8Y291bnQoMSkKNAkxN180MAEbSDI0ODcuNQlpbm5lciBqb2luLCAFDGQ6VGFibGVSZWFkZXJfNDcsIGVxdWFsOltlcRFjDDIyLCANrygyNyldCj |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       HashAgg_32                      root    4       group by:Column#32, funcs:firstrow(Column#32)                                                                                                                                                                           |
|       └─Union_33                      root    4                                                                                                                                                                                                                               |
|         ├─Projection_34               root    1       cast(Column#30)                                                                                                                                                                                                         |
|         │ └─HashAgg_37                root    1       funcs:count(1)                                                                                                                                                                                                          |
|         │   └─HashLeftJoin_40         root    12487.5 inner join, inner:TableReader_47, equal:[eq(Column#22, Column#27)]                                                                                                                                                      |
|         │     ├─TableReader_44        root    9990    data:Selection_43                                                                                                                                                                                                       |
|         │     │ └─Selection_43        cop     9990    not(isnull(Column#22))                                                                                                                                                                                                  |
|         │     │   └─TableScan_42      cop     10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo                                                                                                                                                             |
|         │     └─TableReader_47        root    9990    data:Selection_46                                                                                                                                                                                                       |
|         │       └─Selection_46        cop     9990    not(isnull(Column#27))                                                                                                                                                                                                  |
|         │         └─TableScan_45      cop     10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo                                                                                                                                                             |
|         ├─Projection_50               root    1       cast(Column#20)                                                                                                                                                                                                         |
|         │ └─HashAgg_53                root    1       funcs:count(1)                                                                                                                                                                                                          |
|         │   └─HashLeftJoin_56         root    12487.5 inner join, inner:TableReader_63, equal:[eq(Column#12, Column#17)]                                                                                                                                                      |
|         │     ├─TableReader_60        root    9990    data:Selection_59                                                                                                                                                                                                       |
|         │     │ └─Selection_59        cop     9990    not(isnull(Column#12))                                                                                                                                                                                                  |
|         │     │   └─TableScan_58      cop     10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo                                                                                                                                                             |
|         │     └─TableReader_63        root    9990    data:Selection_62                                                                                                                                                                                                       |
|         │       └─Selection_62        cop     9990    not(isnull(Column#17))                                                                                                                                                                                                  |
|         │         └─TableScan_61      cop     10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo                                                                                                                                                             |
|         ├─Projection_66               root    1       cast(Column#10)                                                                                                                                                                                                         |
|         │ └─HashAgg_69                root    1       funcs:count(1)                                                                                                                                                                                                          |
|         │   └─HashLeftJoin_72         root    12487.5 inner join, inner:TableReader_79, equal:[eq(Column#2, Column#7)]                                                                                                                                                        |
|         │     ├─TableReader_76        root    9990    data:Selection_75                                                                                                                                                                                                       |
|         │     │ └─Selection_75        cop     9990    not(isnull(Column#2))                                                                                                                                                                                                   |
|         │     │   └─TableScan_74      cop     10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo                                                                                                                                                             |
|         │     └─TableReader_79        root    9990    data:Selection_78                                                                                                                                                                                                       |
|         │       └─Selection_78        cop     9990    not(isnull(Column#7))                                                                                                                                                                                                   |
|         │         └─TableScan_77      cop     10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo                                                                                                                                                             |
|         └─Projection_82               root    1       cast(Column#1)                                                                                                                                                                                                          |
|           └─Projection_83             root    1       sleep(1)                                                                                                                                                                                                                |
|             └─TableDual_84            root    1       rows:1                                                                                                                                                                                                                  |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

What is changed and how it works?

  • Add planEncoder and planDecoder.
  • The encode logic is:
    1. first convert the plan to the string of plan tree.
    2. use snappy to compress the string.
    3. use base64 encode.

The performance of snappy is good than zlib.

var input = []byte(`0       5_13    0       1       funcs:count(1)
1       17_14   0       0       inner join, inner:TableReader_21, equal:[eq(Column#1, Column#9) eq(Column#2, Column#10)]
2       32_18   0       0       data:Selection_17
3       1_17    1       0       lt(Column#1, NULL), not(isnull(Column#1)), not(isnull(Column#2))
4       10_16   1       10000   table:t1, range:[-inf,+inf], keep order:false, stats:pseudo
2       32_21   0       0       data:Selection_20
3       1_20    1       0       lt(Column#9, NULL), not(isnull(Column#10)), not(isnull(Column#9))
4       10_19   1       10000   table:t2, range:[-inf,+inf], keep order:false, stats:pseudo`)

func BenchmarkSnappy(b *testing.B) {
	for i := 0; i < b.N; i++ {
		snappyCompress(input)
	}
}

func BenchmarkZlib(b *testing.B) {
	for i := 0; i < b.N; i++ {
		zlibCompress(input)
	}
}

func snappyCompress(input []byte) (string, error) {
	var buf bytes.Buffer
	bs := snappy.Encode(buf.Bytes(), input)
	return string(bs), nil
}

func zlibCompress(input []byte) (string, error) {
	var buf bytes.Buffer
	w := zlib.NewWriter(&buf)
	_, err := w.Write(input)
	if err != nil {
		return "", err
	}
	err = w.Close()
	if err != nil {
		return "", err
	}
	return buf.String(), nil
}
▶ go test -run '^$' -bench .
goos: darwin
goarch: amd64
pkg: github.com/crazycs520/test2
BenchmarkSnappy-12       2000000               714 ns/op
BenchmarkZlib-12           10000            102693 ns/op

Benchmark test

Related PR:

Set tidb_slow_threshold to 0 then do benchmark test.

As you can see, It only has a minimal impact on performance when record plan in the slow log.

Before

@@                               Benchmark Diff                               @@
================================================================================
--- tidb: 7c776be85d4445edd894052cc7585c310be6fca6
+++ tidb: 6c55a0e89b1fb24e6cd2e038dd3bcd00f7a35b36
tikv: 00b0234fecbe97f53700b125ce1f5793ba88531b
pd: 913cd8114b372eff5f037ec0e7f59e73ce2bbf70
================================================================================
test-1: < oltp_point_select >
    * QPS : 33061.64 ± 1.8422% (std=401.69) delta: -57.99% (p=0.000)
    * AvgMs : 7.74 ± 1.8853% (std=0.10) delta: 138.28%
    * PercentileMs99 : 21.50 ± 0.0000% (std=0.00) delta: 224.68%
            
test-2: < oltp_read_write >
    * QPS : 22465.13 ± 0.2941% (std=42.06) delta: -41.21% (p=0.000)
    * AvgMs : 228.86 ± 0.2960% (std=0.44) delta: 70.19%
    * PercentileMs99 : 317.88 ± 1.0796% (std=2.80) delta: 23.23%
            
test-3: < oltp_insert >
    * QPS : 20803.03 ± 0.1548% (std=21.93) delta: -5.83% (p=0.000)
    * AvgMs : 12.30 ± 0.1423% (std=0.01) delta: 6.18%
    * PercentileMs99 : 24.83 ± 0.0000% (std=0.00) delta: 5.57%
            
test-4: < oltp_update_index >
    * QPS : 16808.84 ± 0.3569% (std=43.98) delta: -5.00% (p=0.000)
    * AvgMs : 15.07 ± 0.6369% (std=0.06) delta: 4.17%
    * PercentileMs99 : 32.53 ± 0.0000% (std=0.00) delta: 2.95%
            
test-5: < oltp_update_non_index >
    * QPS : 26969.38 ± 0.2304% (std=37.26) delta: -9.58% (p=0.000)
    * AvgMs : 9.48 ± 0.1318% (std=0.01) delta: 10.52%
    * PercentileMs99 : 23.10 ± 0.0000% (std=0.00) delta: 9.43%

come from https://github.com/pingcap/tidb/pull/12435#issuecomment-539500714

This PR

@@                               Benchmark Diff                               @@
================================================================================
--- tidb: 5754d2db48c379805dc6637e53f4aaac88a08d03
+++ tidb: aa290fbcd0446bd2f9a8d92d4b8f18dba11fdd03
tikv: 00b0234fecbe97f53700b125ce1f5793ba88531b
pd: 913cd8114b372eff5f037ec0e7f59e73ce2bbf70
================================================================================
test-1: < oltp_point_select >
    * QPS : 32083.60 ± 1.5136% (std=322.89) delta: -59.05% (p=0.000)
    * AvgMs : 7.98 ± 1.4791% (std=0.08) delta: 144.35%
    * PercentileMs99 : 21.66 ± 1.0805% (std=0.19) delta: 227.62%
            
test-2: < oltp_read_write >
    * QPS : 22274.50 ± 0.6003% (std=100.29) delta: -41.72% (p=0.000)
    * AvgMs : 230.84 ± 0.6169% (std=1.05) delta: 71.63%
    * PercentileMs99 : 320.17 ± 0.0000% (std=0.00) delta: 24.12%
            
test-3: < oltp_insert >
    * QPS : 20822.39 ± 0.4590% (std=76.27) delta: -5.89% (p=0.000)
    * AvgMs : 12.29 ± 0.5046% (std=0.05) delta: 6.28%
    * PercentileMs99 : 24.83 ± 0.0000% (std=0.00) delta: 5.57%
            
test-4: < oltp_update_index >
    * QPS : 16716.31 ± 0.9649% (std=114.22) delta: -5.34% (p=0.000)
    * AvgMs : 15.17 ± 0.4614% (std=0.04) delta: 4.55%
    * PercentileMs99 : 33.36 ± 1.0791% (std=0.29) delta: 5.20%
            
test-5: < oltp_update_non_index >
    * QPS : 26569.69 ± 0.0832% (std=18.42) delta: -11.11% (p=0.000)
    * AvgMs : 9.63 ± 0.1038% (std=0.01) delta: 12.47%
    * PercentileMs99 : 24.38 ± 0.0000% (std=0.00) delta: 15.49%

come from  https://github.com/pingcap/tidb/pull/12393#issuecomment-539534879

Check List

Tests

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

Code changes

  • Has exported function/method change
  • Has exported variable/fields change

@bb7133 bb7133 added type/3.1 cherry-pick type/enhancement The issue or PR belongs to an enhancement. priority/release-blocker This issue blocks a release. Please solve it ASAP. labels Nov 8, 2019
crazycs520
crazycs520 reviewed Nov 8, 2019
View reviewed changes
Copy link
Contributor

@crazycs520 crazycs520 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@bb7133 bb7133 force-pushed the bb7133/cp-12179-3.1 branch 2 times, most recently from 8d4989e to 1264222 Compare November 10, 2019 15:04
@bb7133 bb7133 added the status/LGT1 Indicates that a PR has LGTM 1. label Nov 11, 2019
@crazycs520
Copy link
Contributor

/run-all-tests

@bb7133
Copy link
Member Author

bb7133 commented Nov 11, 2019

/run-unit-test

djshow832
djshow832 reviewed Nov 11, 2019
View reviewed changes
Copy link
Contributor

@djshow832 djshow832 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@djshow832 djshow832 added the status/LGT2 Indicates that a PR has LGTM 2. label Nov 11, 2019
@bb7133 bb7133 removed the status/LGT1 Indicates that a PR has LGTM 1. label Nov 11, 2019
@djshow832
Copy link
Contributor

Approve

@ngaut ngaut added the status/can-merge Indicates a PR has been approved by a committer. label Nov 11, 2019
@sre-bot
Copy link
Contributor

sre-bot commented Nov 11, 2019

/run-all-tests

@sre-bot sre-bot merged commit 499f7cf into pingcap:release-3.1 Nov 11, 2019
@bb7133 bb7133 deleted the bb7133/cp-12179-3.1 branch December 5, 2019 09:38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@crazycs520 crazycs520 crazycs520 left review comments

@djshow832 djshow832 djshow832 left review comments

@ngaut ngaut ngaut approved these changes

Assignees
No one assigned
Labels
priority/release-blocker This issue blocks a release. Please solve it ASAP. status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2. type/enhancement The issue or PR belongs to an enhancement.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
5 participants
@bb7133 @crazycs520 @djshow832 @sre-bot @ngaut