select very slow on an empty table from delete from xx

[D3Hunter]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

• create cluster with tiup playground
• do the following, we can see query from the empty table takes about 60ms. also test another table with 524288 rows, then empty it with delete from, it takes 440ms to query it.

mysql> create table t(a int);
Query OK, 0 rows affected (0.10 sec)

.... insert data

mysql> delete from t;
Query OK, 65536 rows affected (0.38 sec)

mysql> select count(1) from t;
+----------+
| count(1) |
+----------+
|        0 |
+----------+
1 row in set (0.06 sec)

mysql> show table t regions;
+-----------+-----------+--------------------+-----------+-----------------+-------+------------+---------------+------------+----------------------+------------------+------------------------+------------------+
| REGION_ID | START_KEY | END_KEY            | LEADER_ID | LEADER_STORE_ID | PEERS | SCATTERING | WRITTEN_BYTES | READ_BYTES | APPROXIMATE_SIZE(MB) | APPROXIMATE_KEYS | SCHEDULING_CONSTRAINTS | SCHEDULING_STATE |
+-----------+-----------+--------------------+-----------+-----------------+-------+------------+---------------+------------+----------------------+------------------+------------------------+------------------+
|        14 | t_107_    | t_281474976710649_ |        15 |               1 | 15    |          0 |      23118061 |   16450774 |                   24 |           133569 |                        |                  |
+-----------+-----------+--------------------+-----------+-----------------+-------+------------+---------------+------------+----------------------+------------------+------------------------+------------------+

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-04-26 11:34:15 |
+---------------------+
1 row in set (0.00 sec)

• at first, i thought it related to MVCC, so wait GC and query again, still very slow

...... wait gc finished on table t


mysql> select count(1) from t;
+----------+
| count(1) |
+----------+
|        0 |
+----------+
1 row in set (0.07 sec)

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-04-26 14:18:50 |
+---------------------+
1 row in set (0.00 sec)

• for a new created empty table, query time < 10ms

mysql> create table tt(a int);
Query OK, 0 rows affected (0.11 sec)

mysql> select count(1) from tt;
+----------+
| count(1) |
+----------+
|        0 |
+----------+
1 row in set (0.01 sec)

2. What did you expect to see? (Required)

very fast to query

3. What did you see instead (Required)

slow compared to a new created empty table

4. What is your TiDB version? (Required)

master

[D3Hunter]

the cause is after GC, the kv is not compacted, so it's still scanned, but skipped, see delete_skipped_count

for tidb_ddl_job, we will insert and delete after process, if we have a lot of ddl, such as create 1M tables, query from it will be slow even it's almost empty.

mysql> trace select count(1) from t;
+----------------------------------------------------------------------+-----------------+-------------+
| operation                                                            | startTS         | duration    |
+----------------------------------------------------------------------+-----------------+-------------+
| trace                                                                | 14:39:08.630002 | 61.555167ms |
|   ├─session.ExecuteStmt                                              | 14:39:08.630402 | 2.309916ms  |
|   │ ├─executor.Compile                                               | 14:39:08.630419 | 284.125µs   |
|   │ └─session.runStmt                                                | 14:39:08.631917 | 571.583µs   |
|   │   └─TableReaderExecutor.Open                                     | 14:39:08.632030 | 338.958µs   |
|   │     └─distsql.Select                                             | 14:39:08.632054 | 34.375µs    |
|   │       └─regionRequest.SendReqCtx                                 | 14:39:08.632165 | 59.293666ms |
|   │         └─rpcClient.SendRequest, region ID: 126, type: Cop       | 14:39:08.632446 | 59.000209ms |
|   │           └─tikv.RPC                                             | 14:39:08.632448 | 58.287417ms |
|   │             ├─tikv.Wait                                          | 14:39:08.632448 | 96.75µs     |
|   │             │ └─tikv.GetSnapshot                                 | 14:39:08.632448 | 50.958µs    |
|   │             └─tikv.Process                                       | 14:39:08.632544 | 58.037041ms |
|   ├─*aggregate.HashAggExec.Next                                      | 14:39:08.632722 | 58.802167ms |
|   │ └─*executor.TableReaderExecutor.Next                             | 14:39:08.632795 | 58.700167ms |
|   └─*aggregate.HashAggExec.Next                                      | 14:39:08.691530 | 875ns       |
+----------------------------------------------------------------------+-----------------+-------------+

mysql> explain analyze select count(1) from t;
+----------------------------+----------+---------+-----------+---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| id                         | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                                 | operator info                   | memory    | disk    |
+----------------------------+----------+---------+-----------+---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| HashAgg_11                 | 1.00     | 1       | root      |               | time:99.1ms, loops:2, RU:33.283250, partial_worker:{wall_time:99.112917ms, concurrency:5, task_num:0, tot_wait:495.484584ms, tot_exec:0s, tot_time:495.489583ms, max:99.100916ms, p95:99.100916ms}, final_worker:{wall_time:99.120083ms, concurrency:5, task_num:5, tot_wait:1.542µs, tot_exec:41ns, tot_time:495.515123ms, max:99.104291ms, p95:99.104291ms}  | funcs:count(Column#4)->Column#3 | 17.9 KB   | 0 Bytes |
| └─TableReader_12           | 1.00     | 0       | root      |               | time:99.1ms, loops:1, cop_task: {num: 1, max: 99.1ms, proc_keys: 0, tot_proc: 98.4ms, tot_wait: 85.3µs, rpc_num: 1, rpc_time: 99.1ms, copr_cache_hit_ratio: 0.00, build_task_duration: 11.3µs, max_distsql_concurrency: 1}                                                                                                                                     | data:HashAgg_5                  | 284 Bytes | N/A     |
|   └─HashAgg_5              | 1.00     | 0       | cop[tikv] |               | tikv_task:{time:99ms, loops:1}, scan_detail: {total_keys: 262145, get_snapshot_time: 44.8µs, rocksdb: {delete_skipped_count: 131072, key_skipped_count: 393216, block: {cache_hit_count: 3, read_count: 540, read_byte: 8.41 MB, read_time: 12.5ms}}}                                                                                                          | funcs:count(1)->Column#4        | N/A       | N/A     |
|     └─TableFullScan_10     | 10000.00 | 0       | cop[tikv] | table:t       | tikv_task:{time:99ms, loops:1}                                                                                                                                                                                                                                                                                                                                 | keep order:false, stats:pseudo  | N/A       | N/A     |
+----------------------------+----------+---------+-----------+---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+

[D3Hunter]

we can use tikv ctl to compact manually, after that there's no delete_skipped_count

we need compact default and write cf together in this case

mysql> mysql> explain analyze select * from t where a=19; // add condition to avoid coprocessor cache
+-------------------------+----------+---------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| id                      | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                  | operator info                  | memory    | disk |
+-------------------------+----------+---------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| TableReader_7           | 10.00    | 0       | root      |               | time:921.5µs, loops:1, RU:0.497153, cop_task: {num: 1, max: 854.4µs, proc_keys: 0, tot_proc: 66.5µs, tot_wait: 180.2µs, rpc_num: 1, rpc_time: 818.6µs, copr_cache_hit_ratio: 0.00, build_task_duration: 10µs, max_distsql_concurrency: 1}       | data:Selection_6               | 243 Bytes | N/A  |
| └─Selection_6           | 10.00    | 0       | cop[tikv] |               | tikv_task:{time:0s, loops:1}, scan_detail: {total_keys: 1, get_snapshot_time: 142.5µs, rocksdb: {block: {cache_hit_count: 2}}}                                                                                                                  | eq(test.t.a, 19)               | N/A       | N/A  |
|   └─TableFullScan_5     | 10000.00 | 0       | cop[tikv] | table:t       | tikv_task:{time:0s, loops:1}                                                                                                                                                                                                                    | keep order:false, stats:pseudo | N/A       | N/A  |
+-------------------------+----------+---------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
3 rows in set (0.00 sec)

[lance6716]

maybe related to tikv/tikv#17269

[lance6716]

seems it's fixed in TiKV master. When I just DELETE the table data

mysql> explain analyze select count(1) from t;
+----------------------------+----------+---------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| id                         | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                    | operator info                   | memory    | disk    |
+----------------------------+----------+---------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| HashAgg_11                 | 1.00     | 1       | root      |               | time:1.91s, loops:2, RU:2606.169375, partial_worker:{wall_time:1.912181333s, concurrency:5, task_num:0, tot_wait:9.560748876s, tot_exec:0s, tot_time:9.560758124s, max:1.912164666s, p95:1.912164666s}, final_worker:{wall_time:1.912207583s, concurrency:5, task_num:5, tot_wait:1.501µs, tot_exec:41ns, tot_time:9.560873792s, max:1.912178s, p95:1.912178s}                                                                                    | funcs:count(Column#4)->Column#3 | 5.04 KB   | 0 Bytes |
| └─TableReader_12           | 1.00     | 0       | root      |               | time:1.91s, loops:1, cop_task: {num: 19, max: 1.39s, min: 2.09ms, avg: 694.2ms, p95: 1.39s, tot_proc: 7.79s, tot_wait: 5.37s, copr_cache_hit_ratio: 0.11, build_task_duration: 73.1µs, max_distsql_concurrency: 15}, rpc_info:{Cop:{num_rpc:20, total_time:13.8s}, rpc_errors:{epoch_not_match:1}}, backoff{regionMiss: 2ms}                                                                                                                      | data:HashAgg_5                  | 354 Bytes | N/A     |
|   └─HashAgg_5              | 1.00     | 0       | cop[tikv] |               | tikv_task:{proc max:832ms, min:0s, avg: 438.6ms, p80:577ms, p95:832ms, iters:19, tasks:19}, scan_detail: {total_keys: 33554457, get_snapshot_time: 3.62s, rocksdb: {delete_skipped_count: 225125, key_skipped_count: 33779565, block: {cache_hit_count: 61, read_count: 40748, read_byte: 53.9 MB, read_time: 280.8ms}}}, time_detail: {total_process_time: 7.79s, total_wait_time: 5.37s, total_kv_read_wall_time: 7.79s, tikv_wall_time: 13.2s} | funcs:count(1)->Column#4        | N/A       | N/A     |
|     └─TableFullScan_10     | 10000.00 | 0       | cop[tikv] | table:t       | tikv_task:{proc max:832ms, min:0s, avg: 438.6ms, p80:577ms, p95:832ms, iters:19, tasks:19}                                                                                                                                                                                                                                                                                                                                                        | keep order:false, stats:pseudo  | N/A       | N/A     |
+----------------------------+----------+---------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
4 rows in set (1.92 sec)

wait some times

mysql> explain analyze select count(1) from t;
+----------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| id                         | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                                                      | operator info                   | memory    | disk    |
+----------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| HashAgg_11                 | 1.00     | 1       | root      |               | time:2.62ms, loops:2, RU:9.158708, partial_worker:{wall_time:2.59675ms, concurrency:5, task_num:0, tot_wait:12.619457ms, tot_exec:0s, tot_time:12.625543ms, max:2.528792ms, p95:2.528792ms}, final_worker:{wall_time:2.613458ms, concurrency:5, task_num:5, tot_wait:42.208µs, tot_exec:292ns, tot_time:12.724459ms, max:2.54975ms, p95:2.54975ms}  | funcs:count(Column#4)->Column#3 | 5.04 KB   | 0 Bytes |
| └─TableReader_12           | 1.00     | 0       | root      |               | time:2.54ms, loops:1, cop_task: {num: 19, max: 2.02ms, min: 687.6µs, avg: 1.55ms, p95: 2.02ms, tot_proc: 401.1µs, tot_wait: 11.9ms, copr_cache_hit_ratio: 0.84, build_task_duration: 34.3µs, max_distsql_concurrency: 15}, rpc_info:{Cop:{num_rpc:19, total_time:28.9ms}}                                                                           | data:HashAgg_5                  | 533 Bytes | N/A     |
|   └─HashAgg_5              | 1.00     | 0       | cop[tikv] |               | tikv_task:{proc max:832ms, min:0s, avg: 431.9ms, p80:577ms, p95:832ms, iters:19, tasks:19}, scan_detail: {total_keys: 5, get_snapshot_time: 9.12ms, rocksdb: {key_skipped_count: 2, block: {cache_hit_count: 6}}}, time_detail: {total_process_time: 401.1µs, total_wait_time: 11.9ms, tikv_wall_time: 18.6ms}                                      | funcs:count(1)->Column#4        | N/A       | N/A     |
|     └─TableFullScan_10     | 10000.00 | 0       | cop[tikv] | table:t       | tikv_task:{proc max:832ms, min:0s, avg: 431.9ms, p80:577ms, p95:832ms, iters:19, tasks:19}                                                                                                                                                                                                                                                          | keep order:false, stats:pseudo  | N/A       | N/A     |
+----------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
4 rows in set (0.00 sec)

The delete_skipped_count is gone.

I'll leave this issue open to remind us revert MinJobIDRefresher

[D3Hunter]

tidb have copr cache enabled on default, you need query with a different predicate, such as id < you max id + random

[D3Hunter]

I'll leave this issue open to remind us revert MinJobIDRefresher

that also depends on how fast TiKV can detect and compact them, users might run many general DDLs in some short time window

[lance6716]

tidb have copr cache enabled on default, you need query with a different predicate, such as id < you max id + random

I insert and delete few rows to invalid the cache. You can see key_skipped_count is 2 after compaction. Before it's 33779565.