EXPLAIN ANALYZE shows stale timings, when copr_cache is used.
- Dominant language
- Go
- Stars
- 40.5k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
## Bug Report
Please answer these questions before submitting your issue. Thanks!
### 1. Minimal reproduce step (Required)
```mysql
create table d (a int primary key);
insert into d values (1),(2),(3),(4),(5),(6),(7),(8),(9),(10);
create table t1M (a int auto_increment primary key, b int, c varchar(255));
insert into t1M (b,c) select d.a, d.a from d, d d2, d d3, d d4, d d5, d d6;
analyze table t1M;
select * from t1M where c = "test run";
explain analyze select * from t1M where c = "non-existent";
explain analyze select * from t1M where c = "non-existent";
```
Also `EXPLAIN FOR CONNECTION ` is affected the same way!
### 2. What did you expect to see? (Required)
Correct timings, not something that was from the statement before the current one.
### 3. What did you see instead (Required)
Times that could not have happened, since it used cached values (cooperator cache?)
```mysql
tidb> create table d (a int primary key);
Query OK, 0 rows affected (0.021 sec)
tidb> insert into d values (1),(2),(3),(4),(5),(6),(7),(8),(9),(10);
Query OK, 10 rows affected (0.009 sec)
Records: 10 Duplicates: 0 Warnings: 0
tidb> create table t1M (a int auto_increment primary key, b int, c varchar(255));
Query OK, 0 rows affected (0.019 sec)
tidb> insert into t1M (b,c) select d.a, d.a from d, d d2, d d3, d d4, d d5, d d6;
Query OK, 1000000 rows affected (4.989 sec)
Records: 1000000 Duplicates: 0 Warnings: 0
tidb> analyze table t1M;
Query OK, 0 rows affected, 2 warnings (4.070 sec)
tidb> select * from t1M where c = "test run";
Empty set (0.589 sec)
tidb> explain analyze select * from t1M where c = "non-existent";
+-------------------------+-----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+-----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------+-----------+------+
| TableReader_8 | 648.11 | 0 | root | | time:293.5ms, open:21.9µs, close:5.21µs, loops:1, RU:725.29, cop_task: {num: 1, max: 293.4ms, proc_keys: 1e+06, tot_proc: 293ms, tot_wait: 22.7µs, copr_cache_hit_ratio: 0.00, build_task_duration: 3.83µs, max_distsql_concurrency: 1}, fetch_resp_duration: 293.4ms, rpc_info:{Cop:{num_rpc:1, total_time:293.4ms}} | data:Selection_7 | 311 Bytes | N/A |
| └─Selection_7 | 648.11 | 0 | cop[tikv] | | tikv_task:{time:294ms, loops:981}, scan_detail: {total_process_keys: 1000000, total_process_keys_size: 41100000, total_keys: 1000001, get_snapshot_time: 13µs, rocksdb: {delete_skipped_count: 458036, key_skipped_count: 1458036, block: {cache_hit_count: 2963}}}, time_detail: {total_process_time: 293ms, total_suspend_time: 82.4µs, total_wait_time: 22.7µs, total_kv_read_wall_time: 273ms, tikv_grpc_process_time: 19.5µs, tikv_grpc_wait_time: 18.7µs, tikv_wall_time: 293.2ms} | eq(test.t1m.c, "non-existent") | N/A | N/A |
| └─TableFullScan_6 | 648113.00 | 1000000 | cop[tikv] | table:t1M | tikv_task:{time:273ms, loops:981} | keep order:false, stats:partial[c:unInitialized] | N/A | N/A |
+-------------------------+-----------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------+-----------+------+
3 rows in set (0.295 sec)
tidb> explain analyze select * from t1M where c = "non-existent";
+-------------------------+-----------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+-----------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------+-----------+------+
| TableReader_8 | 648.11 | 0 | root | | time:192.7µs, open:8.5µs, close:2.21µs, loops:1, RU:0.48, cop_task: {num: 1, max: 172.7µs, proc_keys: 0, tot_proc: 459ns, tot_wait: 21.4µs, copr_cache_hit_ratio: 1.00, build_task_duration: 1.54µs, max_distsql_concurrency: 1}, fetch_resp_duration: 177.4µs, rpc_info:{Cop:{num_rpc:1, total_time:167.9µs}} | data:Selection_7 | 246 Bytes | N/A |
| └─Selection_7 | 648.11 | 0 | cop[tikv] | | tikv_task:{time:294ms, loops:981}, scan_detail: {get_snapshot_time: 12.7µs, rocksdb: {block: {}}}, time_detail: {total_process_time: 459ns, total_wait_time: 21.4µs, tikv_grpc_process_time: 14µs, tikv_grpc_wait_time: 11.9µs, tikv_wall_time: 65µs} | eq(test.t1m.c, "non-existent") | N/A | N/A |
| └─TableFullScan_6 | 648113.00 | 1000000 | cop[tikv] | table:t1M | tikv_task:{time:273ms, loops:981} | keep order:false, stats:partial[c:unInitialized] | N/A | N/A |
+-------------------------+-----------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------+-----------+------+
3 rows in set (0.001 sec)
```
Here it is easy to see that the second run took less than 1 ms, but have some timings from the previous command, like time: 273ms, and the `copr_cache_hit_ratio: 1.00` hints that it was fast due to the coprocessor cache, so the issue is probably that either the timings wasn't cleared before the statement started, or it came from the cache?
### 4. What is your TiDB version? (Required)
```
tidb_version(): Release Version: v9.0.0-beta.2.pre-591-gfb8c9c1329
Edition: Community
Git Commit Hash: fb8c9c1329166f1f334ac00552d3960ce2935d7e
Git Branch: HEAD
UTC Build Time: 2025-10-07 16:22:16
GoVersion: go1.23.12
Race Enabled: false
Check Table Before Drop: false
Store: tikv
Kernel Type: Classic
```
Contributor guide
Research direction
Start by reproducing the SQL sequence in the issue on TiDB v9.0.0-beta.2.pre-591-gfb8c9c1329, including both EXPLAIN ANALYZE runs and EXPLAIN FOR CONNECTION. Compare the execution-info timing fields and copr_cache_hit_ratio between runs. Done means cached executions no longer display timing values from the previous statement.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go, sql
- 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