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

Limit executor can't finish Close() quickly after reading required rows #50377

Open
time-and-fate opened this issue Jan 12, 2024 · 0 comments
Open
Labels
sig/execution SIG execution type/enhancement The issue or PR belongs to an enhancement.

Comments

@time-and-fate
Copy link
Member

time-and-fate commented Jan 12, 2024

Phenomenon

The actual return time of the query is much larger than the execution time recorded by operator.

> explain analyze SELECT item_primary_key FROM items WHERE json_overlaps(canonical_links ,  '["qhfZ11841Yv59.com/canonical/link"]') AND (`items`.`point_of_sale_country` = "EN") LIMIT 200;
+------------------------------------+---------+---------+-----------+---------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+------+
| id                                 | estRows | actRows | task      | access object                                                                   | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                       | operator info                                                                                        | memory   | disk |
+------------------------------------+---------+---------+-----------+---------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+------+
| Limit_10                           | 26.44   | 200     | root      |                                                                                 | time:133.1ms, loops:2, RU:6271.731947                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | offset:0, count:200                                                                                  | N/A      | N/A  |
| └─Selection_11                     | 26.44   | 200     | root      |                                                                                 | time:133.1ms, loops:1                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | json_overlaps(test.items.canonical_links, cast("["qhfZ11841Yv59.com/canonical/link"]", json BINARY)) | 310.7 KB | N/A  |
|   └─IndexMerge_18                  | 6.71    | 1024    | root      |                                                                                 | time:131.3ms, loops:1, index_task:{fetch_handle:50.008506ms, merge:44.373317ms}, table_task:{num:8, concurrency:5, fetch_row:1.031669799s, wait_time:55.978619ms}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | type: union                                                                                          | 17.5 MB  | N/A  |
|     ├─IndexRangeScan_15(Build)     | 33.05   | 172448  | cop[tikv] | table:items, index:canonical_links(cast(`canonical_links` as char(1000) array)) | time:3.43ms, loops:155, cop_task: {num: 11, max: 1.25ms, min: 188.9µs, avg: 474.1µs, p95: 1.25ms, max_proc_keys: 992, p95_proc_keys: 992, tot_proc: 1.17ms, tot_wait: 476.9µs, rpc_num: 11, rpc_time: 5.07ms, copr_cache_hit_ratio: 0.73, build_task_duration: 13µs, max_distsql_concurrency: 1}, tikv_task:{proc max:44ms, min:0s, avg: 12ms, p80:28ms, p95:44ms, iters:211, tasks:11}, scan_detail: {total_process_keys: 1696, total_process_keys_size: 248988, total_keys: 1705, get_snapshot_time: 114.7µs, rocksdb: {key_skipped_count: 1702, block: {cache_hit_count: 39}}}                                                                                                                                                                                    | range:["qhfZ11841Yv59.com/canonical/link","qhfZ11841Yv59.com/canonical/link"], keep order:false      | N/A      | N/A  |
|     └─Selection_17(Probe)          | 6.71    | 19230   | cop[tikv] |                                                                                 | time:977.9ms, loops:31, cop_task: {num: 8573, max: 57.3ms, min: 0s, avg: 1.64ms, p95: 7.36ms, max_proc_keys: 29, p95_proc_keys: 17, tot_proc: 8.86s, tot_wait: 6.32s, rpc_num: 4878, rpc_time: 14.1s, copr_cache_hit_ratio: 0.20, build_task_duration: 30.9ms, max_distsql_concurrency: 15, max_extra_concurrency: 117, store_batch_num: 3763, store_batch_fallback_num: 2808}, backoff{regionMiss: 14ms}, tikv_task:{proc max:192ms, min:0s, avg: 8.46ms, p80:9ms, p95:36ms, iters:8573, tasks:8573}, scan_detail: {total_process_keys: 65359, total_process_keys_size: 1350370261, total_keys: 130718, get_snapshot_time: 1.75s, rocksdb: {key_skipped_count: 65363, block: {cache_hit_count: 1050613, read_count: 10225, read_byte: 142.4 MB, read_time: 1.37s}}} | eq(test.items.point_of_sale_country, "EN")                                                           | N/A      | N/A  |
|       └─TableRowIDScan_16          | 33.05   | 96704   | cop[tikv] | table:items                                                                     | tikv_task:{proc max:192ms, min:0s, avg: 8.46ms, p80:9ms, p95:36ms, iters:8573, tasks:8573}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           | keep order:false                                                                                     | N/A      | N/A  |
+------------------------------------+---------+---------+-----------+---------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+------+
6 rows in set, 1 warning (0.415 sec)

You can see the top-level operator recorded ~133ms while the time reported by MySQL cli is 0.415s (network latency is ~30ms).

And in the log, we can find:
image

From the slow query tab in the dashboard:
image

image

Thankfully, this is mentioned before in #40441, and the "limit executor close takes a long time" is added in #40579, which reduces lots of investigation work.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
sig/execution SIG execution type/enhancement The issue or PR belongs to an enhancement.
Projects
None yet
Development

No branches or pull requests

1 participant