pingcap / pingcap/tidb

EXPLAIN ANALYZE shows stale timings, when copr_cache is used.

Open
#63,851 0 comments 0 reactions 0 assignees View on GitHub
sig/planner type/bug
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.