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

executor: add transaction commit runtime informati ... (#19366) #20185

Merged
merged 6 commits into from
Oct 3, 2020
Merged

executor: add transaction commit runtime informati ... (#19366) #20185

merged 6 commits into from
Oct 3, 2020

Conversation

ti-srebot
Copy link
Contributor

cherry-pick #19366 to release-4.0

What problem does this PR solve?

Add transaction commit information to DML plan runtime stats.

Here is an example:

# update

test> select tidb_decode_plan('vQXwWDAJMjhfNAkwCTAJTi9BCTAJdGltZToyNi45OTE4OTRtcywgbG9vcHM6MSwgcHJld3JpdGU6NzgyLjM3wrVzLCBnZXRfY29tbWl0X3RzOjE5NC4wM8K1cywgCRUYOjM2OC4wOQUrNHJlZ2lvbl9udW06NiwgBUoQX2tleXMZDlRieXRlOjE5OAkxLjA4OTg0Mzc1IEtCAZk8CjEJMzFfOAkwCTEuOTkzOR0BMDgJZGF0YTpTZWxlY3QBYQg3CTYZxgw0MDAzHcY0MiwgY29wX3Rhc2s6IHsBi0wgMTAyNCwgbWF4OiAyLjAwODk0MQH2KG1pbjogMTg4LjQ4Bb4kYXZnOiAzNzkuMAngKHA5NTogNTAyLjkyBSAcbWF4X
   -> 3Byb2MJ0wAgIS8EOTUuEgAUMCwgdG90BRIMOiAxNwFkARAcd2FpdDogNDgBEAhycGMlHw2UAQ8lj2AgMzg0LjU5MTczMW1zfQkyLjA3MjI2NTYyNR8cMgkxXzcJMV9SIAFYbHQodGVzdC50MS5hLCAzMDAwMCkJNgkBrgG3ADoV8BgwcywgcDgwCQgEOTUFCBRpdGVyczopJQx0YXNrCQwMCU4vQQEEGAozCTEwXzYFeqg2CXRhYmxlOnQxLCBrZWVwIG9yZGVyOmZhbHNlLCBzdGF0czpwc2V1ZG8J/n0ADX0=');
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('vQXwWDAJMjhfNAkwCTAJTi9BCTAJdGltZToyNi45OTE4OTRtcywgbG9vcHM6MSwgcHJld3JpdGU6NzgyLjM3wrVzLCBnZXRfY29tbWl0X3RzOjE5NC4wM8K1cywgCRUYOjM2OC4wOQUrNHJlZ2lvbl9udW06NiwgBUoQX2tleXMZDlRieXRlOjE5OAkxLjA4OTg0Mzc1IEtCAZk8CjEJMzFfOAkwCTEuOTkzOR0BMDgJZG                                                                                                          |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|     id                   task         estRows               operator info                               actRows    execution info                                                                                                                                                                                                                  memory            disk |
|     Update_4             root         0                     N/A                                         0          time:26.991894ms, loops:1, prewrite:782.37µs, get_commit_ts:194.03µs, commit:368.09µs, region_num:6, write_keys:6, write_byte:198                                                                                            1.08984375 KB     N/A     |
|     └─TableReader_8      root         1.9939999999999998    data:Selection_7                            6          time:26.940034ms, loops:2, cop_task: {num: 1024, max: 2.008941ms, min: 188.48µs, avg: 379.03µs, p95: 502.92µs, max_proc_keys: 1, p95_proc_keys: 0, tot_proc: 17ms, tot_wait: 48ms, rpc_num: 1024, rpc_time: 384.591731ms}    2.072265625 KB    N/A     |
|       └─Selection_7      cop[tikv]    1.9939999999999998    lt(test.t1.a, 30000)                        6          proc max:1ms, min:0s, p80:0s, p95:0s, iters:1024, tasks:1024                                                                                                                                                                    N/A               N/A  |
|         └─TableScan_6    cop[tikv]    6                     table:t1, keep order:false, stats:pseudo    6          proc max:1ms, min:0s, p80:0s, p95:0s, iters:1024, tasks:1024                                                                                                                                                                    N/A               N/A  |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+


# insert when tikv restart

test> select tidb_decode_plan('4wHwbTAJMjdfMQkwCTAJTi9BCTAJdGltZTo0LjMzNDMzMm1zLCBsb29wczoxLCBwcmV3cml0ZTo4LjA2NjQ2OTY0OHMsIGdldF9jb21taXRfdHM6MTI0LjbCtXMsIGNvbW1pdDo5ODQuMzMxwrVzLCBjCSckYmFja29mZjogewVtmCAxNS4yODhzLCB0eXBlOiBbcmVnaW9uTWlzcyB0aWt2UlBDXX0sIAkWUF9udW06MTgsIHdyaXRlX2tleXM6MhEOVGJ5dGU6NjkJMjEzIEJ5dGVzCU4vQQo=');
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('4wHwbTAJMjdfMQkwCTAJTi9BCTAJdGltZTo0LjMzNDMzMm1zLCBsb29wczoxLCBwcmV3cml0ZTo4LjA2NjQ2OTY0OHMsIGdldF9jb21taXRfdHM6MTI0LjbCtXMsIGNvbW1pdDo5ODQuMzMxwrVzLCBjCSckYmFja29mZjogewVtmCAxNS4yODhzLCB0eXBlOiBbcmVnaW9uTWlzcyB0aWt2UlBDXX0sIAkWUF9udW06MT                        |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|     id          task    estRows    operator info    actRows    execution info                                                                                                                                                                                         memory       disk |
|     Insert_1    root    0          N/A              0          time:4.334332ms, loops:1, prewrite:8.066469648s, get_commit_ts:124.6µs, commit:984.331µs, commit_backoff: {time: 15.288s, type: [regionMiss tikvRPC]}, region_num:18, write_keys:2, write_byte:69    213 Bytes    N/A    |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Related changes

  • No

Check List

Tests

  • Unit test
  • Manual test

Side effects

  • Performance regression
    • Consumes more CPU
    • Consumes more MEM

Release note

  • Add transaction commit runtime information in slow log

@crazycs520 @ti-srebot
cherry pick pingcap#19366 to release-4.0
d506d4f 
Signed-off-by: ti-srebot <ti-srebot@pingcap.com>
@ti-srebot
Copy link
Contributor Author

/run-all-tests

@ti-srebot ti-srebot mentioned this pull request Sep 23, 2020
Merged
@ti-srebot ti-srebot added this to the v4.0.7 milestone Sep 23, 2020
qw4990
qw4990 reviewed Sep 23, 2020
View reviewed changes
Copy link
Contributor

@qw4990 qw4990 left a comment

Choose a reason for hiding this comment

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

LGTM

@ti-srebot ti-srebot added the status/LGT1 Indicates that a PR has LGTM 1. label Sep 23, 2020
@lzmhhh123 lzmhhh123 modified the milestones: v4.0.7, v4.0.8 Sep 24, 2020
AilinKid
AilinKid reviewed Sep 28, 2020
View reviewed changes
Copy link
Contributor

@AilinKid AilinKid left a comment

Choose a reason for hiding this comment

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

LGTM

@ti-srebot ti-srebot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Sep 28, 2020
tangenta
tangenta reviewed Sep 28, 2020
View reviewed changes
Copy link
Contributor

@tangenta tangenta left a comment

Choose a reason for hiding this comment

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

LGTM

@ti-srebot ti-srebot added status/LGT3 The PR has already had 3 LGTM. and removed status/LGT2 Indicates that a PR has LGTM 2. labels Sep 28, 2020
@crazycs520
Copy link
Contributor

/run-all-tests

@crazycs520
Copy link
Contributor

/run-unit-test

zz-jason
zz-jason approved these changes Oct 3, 2020
View reviewed changes
Copy link
Member

@zz-jason zz-jason left a comment

Choose a reason for hiding this comment

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

LGTM

@ti-srebot ti-srebot added status/LGT4 The PR has already had 4 LGTM. and removed status/LGT3 The PR has already had 3 LGTM. labels Oct 3, 2020
@zz-jason
Copy link
Member

zz-jason commented Oct 3, 2020

/merge

@ti-srebot ti-srebot added the status/can-merge Indicates a PR has been approved by a committer. label Oct 3, 2020
@ti-srebot
Copy link
Contributor Author

Your auto merge job has been accepted, waiting for:

  • 20297
  • 20293
  • 20155
  • 20074
  • 20252
  • 20240
  • 20248
  • 20249
  • 20216
  • 20154
  • 19944
  • 20210
  • 20205
  • 20214
  • 20170
  • 20182
  • 20151
  • 20146
  • 20172
  • 20046

@zz-jason zz-jason added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT4 The PR has already had 4 LGTM. labels Oct 3, 2020
@ti-srebot
Copy link
Contributor Author

/run-all-tests

@ti-srebot
Copy link
Contributor Author

/run-all-tests

@zz-jason zz-jason changed the title executor: add transaction commit runtime information in slow log (#19366) executor: add transaction commit runtime informati ... (#19366) Oct 3, 2020
@zz-jason zz-jason merged commit 3320248 into pingcap:release-4.0 Oct 3, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@qw4990 qw4990 qw4990 left review comments

@AilinKid AilinKid AilinKid left review comments

@tangenta tangenta tangenta left review comments

@zz-jason zz-jason zz-jason approved these changes

@wshwsh12 wshwsh12 Awaiting requested review from wshwsh12

Assignees

@crazycs520 crazycs520

Labels
component/executor epic/slow-query sig/execution SIG execution status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2. type/4.0-cherry-pick
Projects
None yet
Milestone
v4.0.8
Development

Successfully merging this pull request may close these issues.

None yet
7 participants
@ti-srebot @crazycs520 @zz-jason @qw4990 @AilinKid @tangenta @lzmhhh123