Limit executor can't finish `Close()` quickly after reading required rows
- Dominant language
- Go
- Stars
- 40.6k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
### Phenomenon
The actual return time of the query is much larger than the execution time recorded by operator.
```sql
> 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:

From the slow query tab in the dashboard:


Thankfully, this is mentioned before in https://github.com/pingcap/tidb/issues/40441, and the "limit executor close takes a long time" is added in https://github.com/pingcap/tidb/pull/40579, which reduces lots of investigation work.
Contributor guide
Research direction
Start by reading issue #40441 and pull request #40579, then inspect the limit executor's Close path and reproduce the query shown here. Compare operator execution time with the MySQL client and slow-query measurements; done means the required rows are returned without the remaining Close work causing a large delay.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- databases, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100