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.

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

store/copr: revert pr/35975, do not reduce concurrency for keep order coprocessor request #55141

Merged
merged 2 commits into from
Aug 2, 2024

Conversation

tiancaiamao
Copy link
Contributor

@tiancaiamao tiancaiamao commented Aug 1, 2024

What problem does this PR solve?

Issue Number: close #54969

Problem Summary:

What changed and how does it work?

In the past, #35975 reduce coprocessor concurrency to 2 for the keep order query.
But recently we meet an oncall case that the change cause performance regression.

Balance the memory usage and concurrency is a difficult job, we need more tests and expirements to reach the conclusion.
Currently we can simply set TiFlash to not reduce concurrency, when a user using TiFlash, the tidb memory usage would not be a top concern (their hardware must be better).

Check List

Tests

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

See comments below

  • No need to test
    • I checked and no code files have been changed.

One line change, just revert part of the previous optimization.

Side effects

  • Performance regression: Consumes more CPU
  • Performance regression: Consumes more Memory
  • Breaking backward compatibility

Documentation

  • Affects user behaviors
  • Contains syntax changes
  • Contains variable changes
  • Contains experimental features
  • Changes MySQL compatibility

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

@ti-chi-bot ti-chi-bot bot added release-note-none Denotes a PR that doesn't merit a release note. do-not-merge/needs-tests-checked size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Aug 1, 2024
Copy link

tiprow bot commented Aug 1, 2024

Hi @tiancaiamao. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

Copy link

codecov bot commented Aug 1, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 74.7715%. Comparing base (b0aced8) to head (c1dba47).
Report is 302 commits behind head on master.

Additional details and impacted files
@@               Coverage Diff                @@
##             master     #55141        +/-   ##
================================================
+ Coverage   72.8357%   74.7715%   +1.9358%     
================================================
  Files          1563       1564         +1     
  Lines        438992     440293      +1301     
================================================
+ Hits         319743     329214      +9471     
+ Misses        99562      90861      -8701     
- Partials      19687      20218       +531     
Flag Coverage Δ
integration 49.4739% <44.4444%> (?)
unit 71.7147% <100.0000%> (-0.1204%) ⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Components Coverage Δ
dumpling 52.9567% <ø> (ø)
parser ∅ <ø> (∅)
br 52.5388% <ø> (+6.6388%) ⬆️

@ti-chi-bot ti-chi-bot bot added approved needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Aug 1, 2024
Copy link

ti-chi-bot bot commented Aug 1, 2024

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: lcwangchao, mjonss

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@ti-chi-bot ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Aug 1, 2024
Copy link

ti-chi-bot bot commented Aug 1, 2024

[LGTM Timeline notifier]

Timeline:

  • 2024-08-01 13:22:10.69693771 +0000 UTC m=+9327.915699313: ☑️ agreed by lcwangchao.
  • 2024-08-01 13:44:45.604333721 +0000 UTC m=+10682.823095326: ☑️ agreed by mjonss.

@tiancaiamao
Copy link
Contributor Author

/hold

@ti-chi-bot ti-chi-bot bot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Aug 2, 2024
@ti-chi-bot ti-chi-bot bot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. do-not-merge/needs-tests-checked labels Aug 2, 2024
@tiancaiamao tiancaiamao changed the title store/copr: do not reduce concurrency on tiflash for keep order coprocessor request store/copr: revert pr/35975, do not reduce concurrency for keep order coprocessor request Aug 2, 2024
@tiancaiamao
Copy link
Contributor Author

Reproduce step:

create a cluster

tiup playground nightly --tiflash 0

prepare data:

sysbench --config-file=config oltp_read_only --tables=1 --table-size=25081206   prepare

run an extra tidb using current PR on port 4001, to compare with tidb nightly on port 4000:

./bin/tidb-server -store tikv -path 127.0.0.1:2379 -status 10081 -P 4001

@tiancaiamao
Copy link
Contributor Author

keep order reduce concurrency, explan analyze takes 7.95s

mysql> explain analyze select * from sbtest1 where c = 'sdfsa'  order by id limit 1000;
+------------------------------+------------+----------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------+-----------+------+
| id                           | estRows    | actRows  | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  | operator info                                   | memory    | disk |
+------------------------------+------------+----------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------+-----------+------+
| Limit_12                     | 1000.00    | 0        | root      |               | time:7.95s, loops:1, RU:90980.895122                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            | offset:0, count:1000                            | N/A       | N/A  |
| └─TableReader_25             | 1000.00    | 0        | root      |               | time:7.95s, loops:1, cop_task: {num: 61, max: 419.7ms, min: 232.4ms, avg: 258.1ms, p95: 393.9ms, max_proc_keys: 429003, p95_proc_keys: 410871, tot_proc: 15.7s, tot_wait: 7.38ms, copr_cache_hit_ratio: 0.00, build_task_duration: 117.5µs, max_distsql_concurrency: 2}, rpc_info:{Cop:{num_rpc:61, total_time:15.7s}}                                                                                                                                                                                                          | data:Limit_24                                   | 656 Bytes | N/A  |
|   └─Limit_24                 | 1000.00    | 0        | cop[tikv] |               | tikv_task:{proc max:416ms, min:232ms, avg: 257.2ms, p80:248ms, p95:392ms, iters:24783, tasks:61}, scan_detail: {total_process_keys: 25081206, total_process_keys_size: 5618190144, total_keys: 25081267, get_snapshot_time: 5.83ms, rocksdb: {key_skipped_count: 25081206, block: {cache_hit_count: 157828, read_count: 25490, read_byte: 488.5 MB, read_time: 217.2ms}}}, time_detail: {total_process_time: 15.7s, total_suspend_time: 30.2ms, total_wait_time: 7.38ms, total_kv_read_wall_time: 13.6s, tikv_wall_time: 15.7s} | offset:0, count:1000                            | N/A       | N/A  |
|     └─Selection_23           | 1000.00    | 0        | cop[tikv] |               | tikv_task:{proc max:416ms, min:232ms, avg: 257.2ms, p80:248ms, p95:392ms, iters:24783, tasks:61}                                                                                                                                                                                                                                                                                                                                                                                                                                | eq(sbtest.sbtest1.c, "sdfsa")                   | N/A       | N/A  |
|       └─TableFullScan_22     | 1000000.00 | 25081206 | cop[tikv] | table:sbtest1 | tikv_task:{proc max:392ms, min:168ms, avg: 222.8ms, p80:220ms, p95:356ms, iters:24783, tasks:61}                                                                                                                                                                                                                                                                                                                                                                                                                                | keep order:true, stats:partial[c:unInitialized] | N/A       | N/A  |
+------------------------------+------------+----------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------+-----------+------+
5 rows in set (7.95 sec)

keep order without reduce concurrency, 2.45s

mysql> explain analyze select * from sbtest1 where c = 'sdfsb'  order by id limit 1000;
+------------------------------+------------+----------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------+---------+------+
| id                           | estRows    | actRows  | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                                   | operator info                                                  | memory  | disk |
+------------------------------+------------+----------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------+---------+------+
| Limit_12                     | 1000.00    | 0        | root      |               | time:2.44s, loops:1, RU:94739.204656                                                                                                                                                                                                                                                                                                                                                                                                                             | offset:0, count:1000                                           | N/A     | N/A  |
| └─TableReader_25             | 1000.00    | 0        | root      |               | time:2.44s, loops:1, cop_task: {num: 61, max: 661.7ms, min: 315ms, avg: 553.9ms, p95: 609.8ms, max_proc_keys: 429003, p95_proc_keys: 410871, tot_proc: 27s, tot_wait: 29.4ms, copr_cache_hit_ratio: 0.00, build_task_duration: 536.7µs, max_distsql_concurrency: 15}, rpc_info:{Cop:{num_rpc:61, total_time:33.8s}}                                                                                                                                              | data:Limit_24                                                  | 4.25 KB | N/A  |
|   └─Limit_24                 | 1000.00    | 0        | cop[tikv] |               | tikv_task:{proc max:660ms, min:308ms, avg: 550.3ms, p80:576ms, p95:608ms, iters:24783, tasks:61}, scan_detail: {total_process_keys: 25081206, total_process_keys_size: 5618190144, total_keys: 25081267, get_snapshot_time: 18.1ms, rocksdb: {key_skipped_count: 25081206, block: {cache_hit_count: 183318}}}, time_detail: {total_process_time: 27s, total_suspend_time: 6.75s, total_wait_time: 29.4ms, total_kv_read_wall_time: 29.6s, tikv_wall_time: 33.7s} | offset:0, count:1000                                           | N/A     | N/A  |
|     └─Selection_23           | 1000.00    | 0        | cop[tikv] |               | tikv_task:{proc max:660ms, min:308ms, avg: 550.1ms, p80:576ms, p95:608ms, iters:24783, tasks:61}                                                                                                                                                                                                                                                                                                                                                                 | eq(sbtest.sbtest1.c, "sdfsb")                                  | N/A     | N/A  |
|       └─TableFullScan_22     | 1000000.00 | 25081206 | cop[tikv] | table:sbtest1 | tikv_task:{proc max:588ms, min:256ms, avg: 485.8ms, p80:508ms, p95:536ms, iters:24783, tasks:61}                                                                                                                                                                                                                                                                                                                                                                 | keep order:true, stats:partial[id:allEvicted, c:unInitialized] | N/A     | N/A  |
+------------------------------+------------+----------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------+---------+------+
5 rows in set (2.45 sec)

@tiancaiamao
Copy link
Contributor Author

tiancaiamao commented Aug 2, 2024

Now we focus on this query select * from sbtest1 order by id and it will give us the surprising conclusion.

explan analyze, let keep order coprocessor reduce concurrency, it takes 11.18s

mysql> explain analyze select * from sbtest1  order by id;
+------------------------+-------------+----------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+----------+------+
| id                     | estRows     | actRows  | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                              | operator info         | memory   | disk |
+------------------------+-------------+----------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+----------+------+
| TableReader_11         | 25393824.00 | 25081206 | root      |               | time:11.2s, loops:24541, RU:90622.497982, cop_task: {num: 977, max: 67.9ms, min: 205.3µs, avg: 22.5ms, p95: 47.1ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 17s, tot_wait: 59.3ms, copr_cache_hit_ratio: 0.03, build_task_duration: 125.2µs, max_distsql_concurrency: 2}, rpc_info:{Cop:{num_rpc:977, total_time:21.9s}}                                                                                                                      | data:TableFullScan_10 | 100.3 MB | N/A  |
| └─TableFullScan_10     | 25393824.00 | 25081206 | cop[tikv] | table:sbtest1 | tikv_task:{proc max:52ms, min:0s, avg: 13.7ms, p80:28ms, p95:32ms, iters:28326, tasks:977}, scan_detail: {total_process_keys: 24723658, total_process_keys_size: 5538099392, total_keys: 24724609, get_snapshot_time: 31.7ms, rocksdb: {key_skipped_count: 24723658, block: {cache_hit_count: 184268}}}, time_detail: {total_process_time: 17s, total_suspend_time: 42.3ms, total_wait_time: 59.3ms, total_kv_read_wall_time: 13.1s, tikv_wall_time: 17.3s} | keep order:true       | N/A      | N/A  |
+------------------------+-------------+----------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+----------+------+
2 rows in set (11.18 sec)

And if keep order coprocessor request do not reduce concurrency, the same query takes 5.26s

mysql> explain analyze select * from sbtest1  order by id;
+------------------------+-------------+----------+-----------+---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+----------+------+
| id                     | estRows     | actRows  | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                               | operator info         | memory   | disk |
+------------------------+-------------+----------+-----------+---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+----------+------+
| TableReader_11         | 25393824.00 | 25081206 | root      |               | time:5.26s, loops:24541, RU:99709.887496, cop_task: {num: 977, max: 317.7ms, min: 279.7µs, avg: 75.7ms, p95: 183ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 44.6s, tot_wait: 168.4ms, copr_cache_hit_ratio: 0.06, build_task_duration: 162.8µs, max_distsql_concurrency: 15}, rpc_info:{Cop:{num_rpc:977, total_time:1m13.9s}}                                                                                                                 | data:TableFullScan_10 | 986.0 MB | N/A  |
| └─TableFullScan_10     | 25393824.00 | 25081206 | cop[tikv] | table:sbtest1 | tikv_task:{proc max:108ms, min:0s, avg: 35.1ms, p80:68ms, p95:84ms, iters:28326, tasks:977}, scan_detail: {total_process_keys: 24682602, total_process_keys_size: 5528902848, total_keys: 24683524, get_snapshot_time: 62.5ms, rocksdb: {key_skipped_count: 24682602, block: {cache_hit_count: 183852}}}, time_detail: {total_process_time: 44.6s, total_suspend_time: 2.23s, total_wait_time: 168.4ms, total_kv_read_wall_time: 34s, tikv_wall_time: 50.9s} | keep order:true       | N/A      | N/A  |
+------------------------+-------------+----------+-----------+---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+----------+------+
2 rows in set (5.26 sec)

So far so good.

The surprise comes from the reading resultset from mysql client:

Keep order concurrency = 15,read data from mysql client takes 33.4s
time mysql -h 127.0.0.1 -u root -P 4001 -A -B sbtest -e 'set @@tidb_mem_quota_query = 16000000000; select * from sbtest1  order by id;' > /dev/null

real    0m33.446s
user    0m26.794s
sys     0m4.205s

Keep order concurrency = 2, read data from mysql client takes  35.9s
time mysql -h 127.0.0.1 -u root -P 4000 -A -B sbtest -e 'set @@tidb_mem_quota_query = 1600000000; select * from sbtest1  order by id;' > /dev/null

real    0m35.964s
user    0m29.143s
sys     0m3.261s

Why? why concurrency does not help in such case, while it seems much better in 'explain analyze'?

@tiancaiamao
Copy link
Contributor Author

Conclusion:

It shows that when the result set data is large, the performance bottleneck is that the client receives data through the MySQL protocol, rather than concurrently reading from tikv in tidb.

Because the client receives data with only 1 connection, there is no concurrency.
In the scenario where keep order uses 2 concurrency, the rate at which tidb retrieves data from tikv is greater than that returned to the client from tidb.
Therefore, increasing concurrency will only cause data to be cached in the tidb process and increase memory usage.

In scenarios where the result set is small, MySQL Client reading speed is not a bottleneck, and TiDB memory usage is not a problem, then the higher the concurrency, the better.

@tiancaiamao
Copy link
Contributor Author

/unhold

@ti-chi-bot ti-chi-bot bot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Aug 2, 2024
@ti-chi-bot ti-chi-bot bot merged commit 1536aa8 into pingcap:master Aug 2, 2024
21 checks passed
@tiancaiamao tiancaiamao deleted the tiflash branch August 2, 2024 02:22
tiancaiamao added a commit to tiancaiamao/tidb that referenced this pull request Aug 2, 2024
ti-chi-bot bot pushed a commit that referenced this pull request Aug 2, 2024
@ti-chi-bot ti-chi-bot added the needs-cherry-pick-release-8.1 Should cherry pick this PR to release-8.1 branch. label Aug 5, 2024
@ti-chi-bot
Copy link
Member

In response to a cherrypick label: new pull request created to branch release-8.1: #55177.

@ti-chi-bot ti-chi-bot removed the needs-cherry-pick-release-8.1 Should cherry pick this PR to release-8.1 branch. label Aug 5, 2024
@ti-chi-bot ti-chi-bot bot added the needs-cherry-pick-release-6.5 Should cherry pick this PR to release-6.5 branch. label Aug 26, 2024
@ti-chi-bot
Copy link
Member

In response to a cherrypick label: new pull request created to branch release-6.5: #55640.

@ti-chi-bot ti-chi-bot bot added needs-cherry-pick-release-7.5 Should cherry pick this PR to release-7.5 branch. needs-cherry-pick-release-7.1 Should cherry pick this PR to release-7.1 branch. labels Sep 11, 2024
@ti-chi-bot
Copy link
Member

In response to a cherrypick label: new pull request created to branch release-7.5: #56007.

@ti-chi-bot
Copy link
Member

In response to a cherrypick label: new pull request created to branch release-7.1: #56008.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved lgtm needs-cherry-pick-release-6.5 Should cherry pick this PR to release-6.5 branch. needs-cherry-pick-release-7.1 Should cherry pick this PR to release-7.1 branch. needs-cherry-pick-release-7.5 Should cherry pick this PR to release-7.5 branch. release-note-none Denotes a PR that doesn't merit a release note. size/M Denotes a PR that changes 30-99 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

query is very slow when keep order is true
4 participants