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) #20187

Merged
merged 13 commits into from
Oct 22, 2020
Merged

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

merged 13 commits into from
Oct 22, 2020

Conversation

ti-srebot
Copy link
Contributor

cherry-pick #19574 to release-4.0

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 @ti-srebot
cherry pick pingcap#19574 to release-4.0
387c135 
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-challenge-bot
Copy link

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

More

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

Warning: None

@ti-srebot ti-srebot added contribution This PR is from a community contributor. difficulty/easy sig/execution SIG execution type/4.0-cherry-pick labels Sep 23, 2020
@ti-challenge-bot
Copy link

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

More

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

Warning: None

@ti-srebot ti-srebot added this to the v4.0.7 milestone Sep 23, 2020
@ti-challenge-bot
Copy link

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

More

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

Warning: None

@ti-srebot ti-srebot self-assigned this Sep 23, 2020
@ti-challenge-bot
Copy link

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

More

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

Warning: None

7 similar comments
@ti-challenge-bot
Copy link

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

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 @qw4990.

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 @qw4990.

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 @qw4990.

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 @qw4990.

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 @qw4990.

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 @qw4990.

More

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

Warning: None

qw4990
qw4990 reviewed Sep 23, 2020
View reviewed changes
executor/insert_common.go Outdated
@@ -929,12 +938,37 @@ func (e *InsertValues) handleWarning(err error) {
sc.AppendWarning(err)
}

<<<<<<< HEAD
Copy link
Contributor

Choose a reason for hiding this comment

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

@jyz0309 Please fix conflicts.

@lzmhhh123 lzmhhh123 modified the milestones: v4.0.7, v4.0.8 Sep 24, 2020
@jyz0309
init
9e19eb2 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
add the test
21bcb3a 
Signed-off-by: jyz0309 <45495947@qq.com>
jyz0309 and others added 9 commits October 21, 2020 17:50
@jyz0309
Merge branch 'release-4.0' into release-4.0-bb354b0c3022
bb2b518
@jyz0309
init
b3411fd 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
Merge branch 'release-4.0-bb354b0c3022' of github.com:ti-srebot/tidb …
0149746 
…into release-4.0-bb354b0c3022
@jyz0309
fix check_dev
a857392 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
fix check_dev
c7f00ef 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
fix the test
5b453fd 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
fix test
257313a 
Signed-off-by: jyz0309 <45495947@qq.com>
@jyz0309
make ci happy
8c9a10d 
Signed-off-by: jyz0309 <45495947@qq.com>
@crazycs520
Merge branch 'release-4.0' into release-4.0-bb354b0c3022
611fd45
@crazycs520
Copy link
Contributor

/run-all-tests

crazycs520
crazycs520 reviewed Oct 21, 2020
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

@ti-srebot ti-srebot added the status/LGT1 Indicates that a PR has LGTM 1. label Oct 21, 2020
@crazycs520
Copy link
Contributor

@qw4990 PTAL

qw4990
qw4990 reviewed Oct 21, 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 status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Oct 21, 2020
@SunRunAway
Copy link
Contributor

/merge

@ti-srebot ti-srebot added status/LGT3 The PR has already had 3 LGTM. status/can-merge Indicates a PR has been approved by a committer. and removed status/LGT2 Indicates that a PR has LGTM 2. labels Oct 22, 2020
@ti-srebot
Copy link
Contributor Author

/run-all-tests

@SunRunAway SunRunAway merged commit 73563b0 into pingcap:release-4.0 Oct 22, 2020
@SunRunAway SunRunAway deleted the release-4.0-bb354b0c3022 branch October 22, 2020 05:07
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

@SunRunAway SunRunAway SunRunAway approved these changes

@qw4990 qw4990 qw4990 approved these changes

Assignees

@ti-srebot ti-srebot

Labels
contribution This PR is from a community contributor. sig/execution SIG execution status/can-merge Indicates a PR has been approved by a committer. status/LGT3 The PR has already had 3 LGTM. type/4.0-cherry-pick
Projects
None yet
Milestone
v4.0.8
Development

Successfully merging this pull request may close these issues.
6 participants
@ti-srebot @crazycs520 @SunRunAway @qw4990 @lzmhhh123 @jyz0309