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 the time consuming of memory operation of Insert Executor in Runtime Information #19574

Merged
merged 54 commits into from
Sep 23, 2020
Merged

*:Record the time consuming of memory operation of Insert Executor in Runtime Information #19574

merged 54 commits into from
Sep 23, 2020

Conversation

jyz0309
Copy link
Contributor

@jyz0309 jyz0309 commented Aug 28, 2020 •
edited by ti-srebot
Loading

What problem does this PR solve?

Issue Number: close #19512
Problem Summary:

What is changed and how it works?

What's Changed:
add two extra time-consuming sections in runtime information and trace span
How it Works:
Split inspection and insertion into two parts, and time each part

Related changes

  • PR to update /pingcap/exector:
  • Need to cherry-pick to the release branch

Check List

Tests

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

Side effects
After this pr:

mysql> select tidb_decode_plan('8QLgMAkyN18xCTAJMAlOL0EJMAl0aW1lOjI2Mi4wNDjCtXMsIGxvb3BzOjEsIHByZXBhcmU6MzMuNDI2BRxMY2hlY2tfaW5zZXJ0Ont0b3RhbF8JQRQyOC42MjIFJQxtZW1fMikAGDE1MS4zMjEFHTRwcmVmZXRjaDo3Ny4zMAkUSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgxLCAuYgAMNS4xNwEwBH0sbiYAmDkuMzI3wrVzfX19LCBjb21taXRfdHhuOiB7cHJld3JpdGU6OTQuMQ16DGdldF8RJRRzOjQuOTQFpQkTWDoxLjMwNjU1OG1zLCByZWdpb25fbnVtAZgFSRxfa2V5czoyLA0OWGJ5dGU6NDh9CTE5MiBCeXRlcwlOL0EK');
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('8QLgMAkyN18xCTAJMAlOL0EJMAl0aW1lOjI2Mi4wNDjCtXMsIGxvb3BzOjEsIHByZXBhcmU6MzMuNDI2BRxMY2hlY2tfaW5zZXJ0Ont0b3RhbF8JQRQyOC42MjIFJQxtZW1fMikAGDE1MS4zMjEFHTRwcmVmZXRjaDo3Ny4zMAkUSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgxLCAuYgAMNS4xNwEwBH0sbiYAmDkuMzI3wr                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 	id      	task	estRows	operator info	actRows	execution info                                                                                                                                                                                                                                                                                                                                   	memory   	disk
	Insert_1	root	0      	N/A          	0      	time:262.048µs, loops:1, prepare:33.426µs, check_insert:{total_time:228.622µs, mem_check_insert:151.321µs, prefetch:77.301µs, rpc:{BatchGet:{num_rpc:1, total_time:25.171µs},Get:{num_rpc:1, total_time:29.327µs}}}, commit_txn: {prewrite:94.101µs, get_commit_ts:4.94µs, commit:1.306558ms, region_num:1, write_keys:2, write_byte:48}	192 BytesN/A          |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> select tidb_decode_plan('1AHgMAkyN18xCTAJMAlOL0EJMAl0aW1lOjI1MS44MzHCtXMsIGxvb3BzOjEsIHByZXBhcmU6NjQuOTM4BRxMY2hlY2tfaW5zZXJ0Ont0b3RhbF8FQRgxODYuODkzBSUMbWVtXzIpAAw3Mi4xDV08cHJlZmV0Y2g6MTE0Ljc2MgUxSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgxLCAdYmgzNy4wMDfCtXN9fX0JMTQ0IEJ5dGVzCU4vQQo=');
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('1AHgMAkyN18xCTAJMAlOL0EJMAl0aW1lOjI1MS44MzHCtXMsIGxvb3BzOjEsIHByZXBhcmU6NjQuOTM4BRxMY2hlY2tfaW5zZXJ0Ont0b3RhbF8FQRgxODYuODkzBSUMbWVtXzIpAAw3Mi4xDV08cHJlZmV0Y2g6MTE0Ljc2MgUxSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgxLCAdYmgzNy4wMDfCtXN9fX0JMTQ0IEJ5dG                                                                                                                                                                                                                                 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 	id      	task	estRows	operator info	actRows	execution info                                                                                                                                                                      	memory   	disk
	Insert_1	root	0      	N/A          	0      	time:251.831µs, loops:1, prepare:64.938µs, check_insert:{total_time:186.893µs, mem_check_insert:72.131µs, prefetch:114.762µs, rpc:{BatchGet:{num_rpc:1, total_time:37.007µs}}}	144 Bytes	N/A       |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

mysql> select tidb_decode_plan('1gHgMAkyN18xCTAJMAlOL0EJMAl0aW1lOjI3NS4zNDPCtXMsIGxvb3BzOjEsIHByZXBhcmU6OTguMjExBRw0aW5zZXJ0OjE3Ny4xMzIFE3Bjb21taXRfdHhuOiB7cHJld3JpdGU6MjY4LjQ2OAUiDGdldF8RJhRzOjMuOTMJGAkUGDozOTguMDcFKjRyZWdpb25fbnVtOjEsIAVKEF9rZXlzGQ4EYnkBXUA5fQkxNzMgQnl0ZXMJTi9BCg==');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('1gHgMAkyN18xCTAJMAlOL0EJMAl0aW1lOjI3NS4zNDPCtXMsIGxvb3BzOjEsIHByZXBhcmU6OTguMjExBRw0aW5zZXJ0OjE3Ny4xMzIFE3Bjb21taXRfdHhuOiB7cHJld3JpdGU6MjY4LjQ2OAUiDGdldF8RJhRzOjMuOTMJGAkUGDozOTguMDcFKjRyZWdpb25fbnVtOjEsIAVKEF9rZXlzGQ4EYnkBXUA5fQkxNzMgQn                                                                                                                                                                                                                                     |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 	id      	task	estRows	operator info	actRows	execution info                                                                                                                                                                        	memory   	disk
	Insert_1	root	0      	N/A          	0      	time:275.343µs, loops:1, prepare:98.211µs, insert:177.132µs, commit_txn: {prewrite:268.468µs, get_commit_ts:3.938µs, commit:398.07µs, region_num:1, write_keys:1, write_byte:29}	173 Bytes	N/A       |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> trace format='log' insert into t values(10,1) on duplicate key update `a`=`a`+1;
+----------------------------+------------------------------------------------------------------------+------+--------------------------------+
| time                       | event                                                                  | tags | spanName                       |
+----------------------------+------------------------------------------------------------------------+------+--------------------------------+
| 2020-09-17 19:24:08.424576 | --- start span trace ----                                              |      | trace                          |
| 2020-09-17 19:24:08.424587 | --- start span session.Execute ----                                    |      | session.Execute                |
| 2020-09-17 19:24:08.424592 | execute: insert into t values(10,1) on duplicate key update `a`=`a`+1  |      | session.Execute                |
| 2020-09-17 19:24:08.424593 | --- start span session.ParseSQL ----                                   |      | session.ParseSQL               |
| 2020-09-17 19:24:08.424610 | --- start span session.ExecuteStmt ----                                |      | session.ExecuteStmt            |
| 2020-09-17 19:24:08.424612 | --- start span executor.Compile ----                                   |      | executor.Compile               |
| 2020-09-17 19:24:08.424722 | --- start span session.runStmt ----                                    |      | session.runStmt                |
| 2020-09-17 19:24:08.424749 | --- start span executor.handleNoDelayExecutor ----                     |      | executor.handleNoDelayExecutor |
| 2020-09-17 19:24:08.424752 | --- start span *executor.InsertExec.Next ----                          |      | *executor.InsertExec.Next      |
| 2020-09-17 19:24:08.424783 | insert 1 rows into table `t`                                           |      | *executor.InsertExec.Next      |
| 2020-09-17 19:24:08.424829 | --- start span prefetchDataCache ----                                  |      | prefetchDataCache              |
| 2020-09-17 19:24:08.424836 | --- start span prefetchUniqueIndices ----                              |      | prefetchUniqueIndices          |
| 2020-09-17 19:24:08.424841 | --- start span tikvTxn.BatchGet ----                                   |      | tikvTxn.BatchGet               |
| 2020-09-17 19:24:08.424876 | load region 66 from pd, due to cache-miss                              |      | tikvTxn.BatchGet               |
| 2020-09-17 19:24:08.424882 | --- start span regionReqauest.SendReqCtx ----                          |      | regionReqauest.SendReqCtx      |
| 2020-09-17 19:24:08.424890 | send BatchGet request to region 66 at store1                           |      | regionReqauest.SendReqCtx      |
| 2020-09-17 19:24:08.424918 | --- start span prefetchConflictedOldRows ----                          |      | prefetchConflictedOldRows      |
| 2020-09-17 19:24:08.424919 | --- start span tikvTxn.BatchGet ----                                   |      | tikvTxn.BatchGet               |
| 2020-09-17 19:24:08.424947 | --- start span executor.updateRecord ----                              |      | executor.updateRecord          |
| 2020-09-17 19:24:08.424981 | --- start span tikvSnapshot.get ----                                   |      | tikvSnapshot.get               |
| 2020-09-17 19:24:08.424984 | --- start span regionReqauest.SendReqCtx ----                          |      | regionReqauest.SendReqCtx      |
| 2020-09-17 19:24:08.424986 | send Get request to region 66 at store1                                |      | regionReqauest.SendReqCtx      |
| 2020-09-17 19:24:08.425057 | --- start span session.RollbackTxn ----                                |      | session.RollbackTxn            |
| 2020-09-17 19:24:08.425108 | execute with error(0): [kv:1062]Duplicate entry '11' for key 'PRIMARY' |      | trace                          |
+----------------------------+------------------------------------------------------------------------+------+--------------------------------+
24 rows in set, 1 warning (0.00 sec)
  • Performance regression
    • Consumes more CPU
    • Consumes more MEM

Release note

  • add two extra time-consuming sections in runtime information and trace span

@jyz0309
init
d4d75a8 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
update trace
7b7b7c8 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
update trace batchCheckAndInsert
c8287b9 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
check-dev
278fc96 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
update comment
6112068 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
init
ffec1b5 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
update the duration about check and insert
27b4732 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309 jyz0309 requested a review from a team as a code owner August 28, 2020 08:34
@jyz0309 jyz0309 requested review from SunRunAway and removed request for a team August 28, 2020 08:34
@jyz0309 jyz0309 changed the title Record the time consuming of memory operation of Insert Executor in Runtime Information *:Record the time consuming of memory operation of Insert Executor in Runtime Information Aug 28, 2020
@ti-srebot ti-srebot added the contribution This PR is from a community contributor. label Aug 28, 2020
@github-actions github-actions bot added the sig/execution SIG execution label Aug 28, 2020
@jyz0309
Copy link
Contributor Author

jyz0309 commented Aug 28, 2020

/run-unit-test

@jyz0309
test and make ci good
09959fa 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
get line
5bc2779 
Signed-off-by: jyz0309 <45495947@qq.com>
SunRunAway
SunRunAway reviewed Aug 28, 2020
View reviewed changes
store/tikv/snapshot.go Show resolved Hide resolved
executor/insert_common.go Show resolved Hide resolved
executor/insert_common.go Show resolved Hide resolved
crazycs520
crazycs520 reviewed Aug 28, 2020
View reviewed changes
executor/point_get.go Outdated Show resolved Hide resolved
crazycs520
crazycs520 reviewed Aug 28, 2020
View reviewed changes
executor/point_get.go Outdated Show resolved Hide resolved
@jyz0309
init
b295c62 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
debug and pass the unit-test
b76a420 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
Copy link
Contributor Author

jyz0309 commented Sep 2, 2020

/run-all-tests

@jyz0309
pass the test
9182f03 
Signed-off-by: jyz0309 <45495947@qq.com>
@crazycs520
Copy link
Contributor

@jyz0309 Any update?

@jyz0309
init
a9bfd2f 
Signed-off-by: jyz0309 <45495947@qq.com>
@sre-bot
Copy link
Contributor

sre-bot commented Sep 8, 2020

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

@jyz0309
add insertRuntimeStat
9a5dc57 
Signed-off-by: jyz0309 <45495947@qq.com>
@ti-challenge-bot
Copy link

There is no reward for this challenge pull request, so you can request a reward from @SunRunAway.

More

Tip : About reward you can refs to reward-command.

Warning: None

@ti-challenge-bot
Copy link

There is no reward for this challenge pull request, so you can request a reward from @SunRunAway.

More

Tip : About reward you can refs to reward-command.

Warning: None

@qw4990
Copy link
Contributor

qw4990 commented Sep 23, 2020

/reward 300

@ti-challenge-bot
Copy link

This PR's linked issue is not picked.

@ti-challenge-bot
Copy link

There is no reward for this challenge pull request, so you can request a reward from @SunRunAway.

More

Tip : About reward you can refs to reward-command.

Warning: None

@qw4990
Copy link
Contributor

qw4990 commented Sep 23, 2020

/rebuild

@ti-challenge-bot
Copy link

There is no reward for this challenge pull request, so you can request a reward from @SunRunAway.

More

Tip : About reward you can refs to reward-command.

Warning: None

@qw4990
Copy link
Contributor

qw4990 commented Sep 23, 2020

/rebuild

@ti-challenge-bot
Copy link

There is no reward for this challenge pull request, so you can request a reward from @SunRunAway.

More

Tip : About reward you can refs to reward-command.

Warning: None

@jyz0309
Copy link
Contributor Author

jyz0309 commented Sep 23, 2020

@SunRunAway @qw4990 @crazycs520 PTAL, maybe it can be merged:)

@qw4990
Copy link
Contributor

qw4990 commented Sep 23, 2020

/rebuild

@qw4990
Copy link
Contributor

qw4990 commented Sep 23, 2020

/reward 300

@ti-challenge-bot
Copy link

You are not the mentor for the linked issue.

@qw4990
Copy link
Contributor

qw4990 commented Sep 23, 2020

/reward 300

@ti-challenge-bot
Copy link

Reward success.

@qw4990 qw4990 merged commit bb354b0 into pingcap:master Sep 23, 2020
@ti-challenge-bot
Copy link

@jyz0309, Congratulations, you get 300 in this PR, and your total score is 300 in high-performance challenge program.

ti-srebot pushed a commit to ti-srebot/tidb that referenced this pull request Sep 23, 2020
@jyz0309 @ti-srebot
cherry pick pingcap#19574 to release-4.0
387c135 
Signed-off-by: ti-srebot <ti-srebot@pingcap.com>
@ti-srebot ti-srebot mentioned this pull request Sep 23, 2020
Merged
@ti-srebot
Copy link
Contributor

cherry pick to release-4.0 in PR #20187

jyz0309 added a commit to jyz0309/tidb that referenced this pull request Sep 23, 2020
@jyz0309
Revert "*:Record the time consuming of memory operation of Insert Exe…
355dda8 
…cutor in Runtime Information (pingcap#19574)"

This reverts commit bb354b0.
@crazycs520 crazycs520 mentioned this pull request Oct 13, 2020
Closed
SunRunAway pushed a commit that referenced this pull request Oct 22, 2020
@ti-srebot
*:Record the time consuming of memory operation of Insert Executor in…
73563b0 
… Runtime Information (#19574) (#20187)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@SunRunAway SunRunAway SunRunAway left review comments

@qw4990 qw4990 qw4990 left review comments

@crazycs520 crazycs520 crazycs520 left review comments

@ti-srebot ti-srebot ti-srebot approved these changes

Assignees
No one assigned
Labels
contribution This PR is from a community contributor. sig/execution SIG execution status/LGT2 Indicates that a PR has LGTM 2.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Record the time consuming of memory operation of Insert Executor in Runtime Information
6 participants
@jyz0309 @crazycs520 @sre-bot @SunRunAway @qw4990 @ti-srebot