Explain analyze delete from doesn't work as expected

[Connor1996]

Bug Report

1. Minimal reproduce step (Required)

• sysbench prepare with 10000000 rows
• run below by script without stop between each SQL(manual execute one by one can't reproduce)

mysql -uroot -D sbtest -e "select count(*) from sbtest where id < 10000000 limit 10000;"
mysql -uroot -D sbtest -e "explain analyze delete from sbtest where id < 10000000 limit 10000;" 
mysql -uroot -D sbtest -e "explain analyze delete from sbtest where id < 10000000 limit 10000;"
mysql -uroot -D sbtest -e "explain analyze delete from sbtest where id < 10000000 limit 10000;"
mysql -uroot -D sbtest -e "explain analyze delete from sbtest where id < 10000000 limit 10000;"
mysql -uroot -D sbtest -e "explain analyze delete from sbtest where id < 10000000 limit 10000;"
mysql -uroot -D sbtest -e "select count(*) from sbtest where id < 10000000 limit 10000;"

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

the first select count() - the second select count() = 50000

3. What did you see instead (Required)

the first select count() - the second select count() < 50000

4. What is your TiDB version? (Required)

Release Version: v6.3.0-alpha
Edition: Community
Git Commit Hash: 8b5b724d8a932239303a1d0ba547323eb0e5161b
Git Branch: heads/refs/tags/v6.3.0-alpha
UTC Build Time: 2022-08-19 14:31:05
GoVersion: go1.18.5
Race Enabled: false
TiKV Min Version: 6.2.0-alpha
Check Table Before Drop: false

[keeplearning20221]

https://docs.pingcap.com/zh/tidb/stable/sql-statement-explain-analyze

[Connor1996]

@keeplearning20221 Yes, just as the doc said these delete are executed. But the result is not correct

[xuyifangreeneyes]

It can be reproduced by running the script as follows:

mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "select count(*) from sbtest1 where id < 100000000;"
for i in {1..5}
do
echo round$i
time mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "explain analyze delete from sbtest1 where id < 10000000 limit 10000;"
done
mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "select count(*) from sbtest1 where id < 100000000;"

[xuyifangreeneyes]

After five explain analyze delete statements are finished, we can still see explain analyze delete from show processlist.

mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "select count(*) from sbtest1 where id < 100000000;"
for i in {1..5}
do
echo round$i
time mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "explain analyze delete from sbtest1 where id < 10000000 limit 10000;"
done
mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "select count(*) from sbtest1 where id < 100000000;"
mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "show processlist;"
mysql -uroot -P4000 -h 127.0.0.1 -D sbtest -e "select count(*) from sbtest1 where id < 100000000;"

+----------+
| count(*) |
+----------+
|  9600000 |
+----------+
round1
+-------------------------------+----------+---------+-----------+---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| id                            | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                           | operator info                           | memory   | disk |
+-------------------------------+----------+---------+-----------+---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| Delete_5                      | N/A      | 0       | root      |               | time:437.4ms, loops:1                                                                                                                                                                                                                                                                                                    | N/A                                     | 757.8 KB | N/A  |
| └─Limit_9                     | 10000.00 | 10000   | root      |               | time:386.6ms, loops:12                                                                                                                                                                                                                                                                                                   | offset:0, count:10000                   | N/A      | N/A  |
|   └─TableReader_13            | 10000.00 | 10816   | root      |               | time:386.6ms, loops:11, cop_task: {num: 7, max: 196ms, min: 1.52ms, avg: 57.7ms, p95: 196ms, max_proc_keys: 4118, p95_proc_keys: 4118, tot_proc: 384ms, tot_wait: 2ms, rpc_num: 7, rpc_time: 403.8ms, copr_cache: disabled, distsql_concurrency: 1}                                                                      | data:Limit_12                           | 1.43 MB  | N/A  |
|     └─Limit_12                | 10000.00 | 10870   | cop[tikv] |               | tikv_task:{proc max:195ms, min:0s, avg: 55ms, p80:178ms, p95:195ms, iters:35, tasks:7}, scan_detail: {total_process_keys: 10870, total_process_keys_size: 2434880, total_keys: 1391747, get_snapshot_time: 294.6µs, rocksdb: {delete_skipped_count: 40000, key_skipped_count: 1403276, block: {cache_hit_count: 1967}}}  | offset:0, count:10000                   | N/A      | N/A  |
|       └─TableRangeScan_11     | 10000.00 | 10870   | cop[tikv] | table:sbtest1 | tikv_task:{proc max:195ms, min:0s, avg: 55ms, p80:178ms, p95:195ms, iters:35, tasks:7}                                                                                                                                                                                                                                   | range:[-inf,10000000), keep order:false | N/A      | N/A  |
+-------------------------------+----------+---------+-----------+---------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+

real    0m0.484s
user    0m0.008s
sys     0m0.004s
round2
+-------------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| id                            | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                              | operator info                           | memory   | disk |
+-------------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| Delete_5                      | N/A      | 0       | root      |               | time:1.01s, loops:1                                                                                                                                                                                                                                                                                                         | N/A                                     | 757.8 KB | N/A  |
| └─Limit_9                     | 10000.00 | 10000   | root      |               | time:947.7ms, loops:12                                                                                                                                                                                                                                                                                                      | offset:0, count:10000                   | N/A      | N/A  |
|   └─TableReader_13            | 10000.00 | 10816   | root      |               | time:947.7ms, loops:11, cop_task: {num: 7, max: 450.6ms, min: 3.29ms, avg: 98.6ms, p95: 450.6ms, max_proc_keys: 4118, p95_proc_keys: 4118, tot_proc: 676ms, tot_wait: 1ms, rpc_num: 8, rpc_time: 964.4ms, copr_cache: disabled, distsql_concurrency: 1}, ResolveLock:{num_rpc:1, total_time:830.1µs}                        | data:Limit_12                           | 1.43 MB  | N/A  |
|     └─Limit_12                | 10000.00 | 10870   | cop[tikv] |               | tikv_task:{proc max:447ms, min:3ms, avg: 96.6ms, p80:199ms, p95:447ms, iters:35, tasks:7}, scan_detail: {total_process_keys: 10870, total_process_keys_size: 2434880, total_keys: 1401747, get_snapshot_time: 308.9µs, rocksdb: {delete_skipped_count: 86912, key_skipped_count: 1460188, block: {cache_hit_count: 1967}}}  | offset:0, count:10000                   | N/A      | N/A  |
|       └─TableRangeScan_11     | 10000.00 | 10870   | cop[tikv] | table:sbtest1 | tikv_task:{proc max:447ms, min:3ms, avg: 96.6ms, p80:199ms, p95:447ms, iters:35, tasks:7}                                                                                                                                                                                                                                   | range:[-inf,10000000), keep order:false | N/A      | N/A  |
+-------------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+

real    0m1.035s
user    0m0.009s
sys     0m0.005s
round3
+-------------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| id                            | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                              | operator info                           | memory   | disk |
+-------------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| Delete_5                      | N/A      | 0       | root      |               | time:666.1ms, loops:1                                                                                                                                                                                                                                                                                                       | N/A                                     | 757.8 KB | N/A  |
| └─Limit_9                     | 10000.00 | 10000   | root      |               | time:594.6ms, loops:12                                                                                                                                                                                                                                                                                                      | offset:0, count:10000                   | N/A      | N/A  |
|   └─TableReader_13            | 10000.00 | 10662   | root      |               | time:594.6ms, loops:11, cop_task: {num: 10, max: 363.6ms, min: 1.47ms, avg: 61.5ms, p95: 363.6ms, max_proc_keys: 5088, p95_proc_keys: 5088, tot_proc: 598ms, rpc_num: 10, rpc_time: 615.1ms, copr_cache: disabled, distsql_concurrency: 1}                                                                                  | data:Limit_12                           | 1.63 MB  | N/A  |
|     └─Limit_12                | 10000.00 | 12710   | cop[tikv] |               | tikv_task:{proc max:363ms, min:0s, avg: 58.9ms, p80:208ms, p95:363ms, iters:45, tasks:10}, scan_detail: {total_process_keys: 12710, total_process_keys_size: 2847040, total_keys: 1432841, get_snapshot_time: 487.2µs, rocksdb: {delete_skipped_count: 50000, key_skipped_count: 1454367, block: {cache_hit_count: 2037}}}  | offset:0, count:10000                   | N/A      | N/A  |
|       └─TableRangeScan_11     | 10000.00 | 12710   | cop[tikv] | table:sbtest1 | tikv_task:{proc max:363ms, min:0s, avg: 58.9ms, p80:208ms, p95:363ms, iters:45, tasks:10}                                                                                                                                                                                                                                   | range:[-inf,10000000), keep order:false | N/A      | N/A  |
+-------------------------------+----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+

real    0m0.692s
user    0m0.008s
sys     0m0.004s
round4
+-------------------------------+----------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| id                            | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                               | operator info                           | memory   | disk |
+-------------------------------+----------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| Delete_5                      | N/A      | 0       | root      |               | time:842.7ms, loops:1                                                                                                                                                                                                                                                                                                        | N/A                                     | 757.8 KB | N/A  |
| └─Limit_9                     | 10000.00 | 10000   | root      |               | time:786.7ms, loops:12                                                                                                                                                                                                                                                                                                       | offset:0, count:10000                   | N/A      | N/A  |
|   └─TableReader_13            | 10000.00 | 10662   | root      |               | time:786.7ms, loops:11, cop_task: {num: 10, max: 499.7ms, min: 1.48ms, avg: 81ms, p95: 499.7ms, max_proc_keys: 5088, p95_proc_keys: 5088, tot_proc: 786ms, tot_wait: 1ms, rpc_num: 10, rpc_time: 809.3ms, copr_cache: disabled, distsql_concurrency: 1}                                                                      | data:Limit_12                           | 1.63 MB  | N/A  |
|     └─Limit_12                | 10000.00 | 12710   | cop[tikv] |               | tikv_task:{proc max:491ms, min:1ms, avg: 79.1ms, p80:274ms, p95:491ms, iters:45, tasks:10}, scan_detail: {total_process_keys: 12710, total_process_keys_size: 2847040, total_keys: 1445430, get_snapshot_time: 401.6µs, rocksdb: {delete_skipped_count: 92511, key_skipped_count: 1508669, block: {cache_hit_count: 2037}}}  | offset:0, count:10000                   | N/A      | N/A  |
|       └─TableRangeScan_11     | 10000.00 | 12710   | cop[tikv] | table:sbtest1 | tikv_task:{proc max:491ms, min:1ms, avg: 79.1ms, p80:274ms, p95:491ms, iters:45, tasks:10}                                                                                                                                                                                                                                   | range:[-inf,10000000), keep order:false | N/A      | N/A  |
+-------------------------------+----------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+

real    0m0.923s
user    0m0.008s
sys     0m0.005s
round5
+-------------------------------+----------+---------+-----------+---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| id                            | estRows  | actRows | task      | access object | execution info                                                                                                                                                                                                                                                                                                             | operator info                           | memory   | disk |
+-------------------------------+----------+---------+-----------+---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+
| Delete_5                      | N/A      | 0       | root      |               | time:903.7ms, loops:1                                                                                                                                                                                                                                                                                                      | N/A                                     | 757.8 KB | N/A  |
| └─Limit_9                     | 10000.00 | 10000   | root      |               | time:844.2ms, loops:12                                                                                                                                                                                                                                                                                                     | offset:0, count:10000                   | N/A      | N/A  |
|   └─TableReader_13            | 10000.00 | 10662   | root      |               | time:844.2ms, loops:11, cop_task: {num: 10, max: 293.1ms, min: 1.05ms, avg: 53.8ms, p95: 293.1ms, max_proc_keys: 5088, p95_proc_keys: 5088, tot_proc: 526ms, rpc_num: 11, rpc_time: 870.8ms, copr_cache: disabled, distsql_concurrency: 1}, ResolveLock:{num_rpc:1, total_time:468.7µs}                                    | data:Limit_12                           | 2.86 MB  | N/A  |
|     └─Limit_12                | 10000.00 | 12710   | cop[tikv] |               | tikv_task:{proc max:292ms, min:1ms, avg: 53ms, p80:202ms, p95:292ms, iters:45, tasks:10}, scan_detail: {total_process_keys: 12710, total_process_keys_size: 2847040, total_keys: 1455430, get_snapshot_time: 400.8µs, rocksdb: {delete_skipped_count: 93374, key_skipped_count: 1605417, block: {cache_hit_count: 2037}}}  | offset:0, count:10000                   | N/A      | N/A  |
|       └─TableRangeScan_11     | 10000.00 | 12710   | cop[tikv] | table:sbtest1 | tikv_task:{proc max:292ms, min:1ms, avg: 53ms, p80:202ms, p95:292ms, iters:45, tasks:10}                                                                                                                                                                                                                                   | range:[-inf,10000000), keep order:false | N/A      | N/A  |
+-------------------------------+----------+---------+-----------+---------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+----------+------+

real    0m0.975s
user    0m0.008s
sys     0m0.004s
+----------+
| count(*) |
+----------+
|  9580000 |
+----------+
+---------------------+------+-----------------+--------+---------+------+------------+---------------------------------------------------------------------+
| Id                  | User | Host            | db     | Command | Time | State      | Info                                                                |
+---------------------+------+-----------------+--------+---------+------+------------+---------------------------------------------------------------------+
| 4853077199235842643 | root | 127.0.0.1:49899 | sbtest | Query   |    3 | autocommit | explain analyze delete from sbtest1 where id < 10000000 limit 10000 |
| 4853077199235842637 | root | 127.0.0.1:49888 | sbtest | Query   |    6 | autocommit | explain analyze delete from sbtest1 where id < 10000000 limit 10000 |
| 4853077199235842647 | root | 127.0.0.1:49910 | sbtest | Query   |    0 | autocommit | show processlist                                                    |
| 4853077199235842455 | root | 127.0.0.1:58030 | sbtest | Sleep   |   59 | autocommit | NULL                                                                |
+---------------------+------+-----------------+--------+---------+------+------------+---------------------------------------------------------------------+
+----------+
| count(*) |
+----------+
|  9570000 |
+----------+

[xuyifangreeneyes]

The problem still exists after disabling async-commit and copr-cache.

[cfzjywxk]

As it's not common usage and the previous version could also be affected by it, the severity could be lowered then it's non-blocking.

[xuyifangreeneyes]

v6.2 also has the problem.

[cfzjywxk]

The DML executors in explain statement would be handled separately using handleNoDelayExecutor during the process, after this, the execution result is saved into the transaction memory buffer, note here that the transaction is not committed yet. Then the analyze statement is executed and a RecordSet is returned, the record set is returned to the client directly and the client receives all the results. But the actual commit happens in the finishStmt after the closing of the record set. Thus from the client side the analyze statement is finished but the transaction commit is still ongoing.