explain analyze 结果中父算子的time比子算子的time要小，为什么？

🪐 TiDB 技术问题
,
1

【 TiDB 使用环境】测试
【 TiDB 版本】
【复现路径】做explain analyze时发现，一些计划中的子算子Selection/IndexRangeScan【cop(tikv)】的执行时间比父算子（IndexReader）的time要长？这是为什么？其他大部分的执行计划都满足父算子时间>=子算子时间

"query": "SELECT production_year FROM imdb.title USE INDEX(idx1) WHERE production_year>=1912 AND production_year<=1912 AND kind_id>=0 AND kind_id<=6 AND season_nr>=2 AND season_nr<=59",
"plan": [
  "id\testRows\testCost\tactRows\ttask\taccess object\texecution info\toperator info\tmemory\tdisk",
  "Projection_4\t0.00\t85423.07\t0\troot\t\ttime:115.7µs, loops:1, Concurrency:OFF\timdb.title.production_year, row_size: 8\t1.11 KB\tN/A",
  "└─IndexReader_7\t0.00\t85417.07\t0\troot\t\ttime:112.8µs, loops:1, cop_task: {num: 1, max: 7.62ms, proc_keys: 7536, tot_proc: 8ms, rpc_num: 1, rpc_time: 7.59ms, copr_cache: disabled}\tindex:Selection_6, row_size: 48\t232 Bytes\tN/A",
  "  └─Selection_6\t0.00\t85397.07\t0\tcop[tikv]\t\ttikv_task:{time:8ms, loops:12}, scan_detail: {total_process_keys: 7536, total_process_keys_size: 482304, total_keys: 7537, rocksdb: {delete_skipped_count: 0, key_skipped_count: 7536, block: {cache_hit_count: 12, read_count: 0, read_byte: 0 Bytes}}}\tge(imdb.title.season_nr, 2), le(imdb.title.season_nr, 59), row_size: 48\tN/A\tN/A",
  "    └─IndexRangeScan_5\t7536.00\t62789.07\t7536\tcop[tikv]\ttable:title, index:idx1(production_year, kind_id, season_nr)\ttikv_task:{time:8ms, loops:12}\trange:[1912 0,1912 6], keep order:false, row_size: 48\tN/A\tN/A"
]

image
image1798×182 36.6 KB

【遇到的问题：问题现象及影响】
【资源配置】进入到 TiDB Dashboard -集群信息 (Cluster Info) -主机(Hosts) 截图此页面
【附件：截图/日志/监控】

2

哪里显示子算子执行时间比父算子执行时间长？

3

selection这里时间是8ms，上层的index_reader只有115.7µs

4

https://docs.pingcap.com/zh/tidb/dev/explain-overview 因为有一些是多个节点之和的时间。

5

但在我的例子中，只有一个cop_task，对应一个tikv_task，执行了8ms，而indexReader的时间明显低于该时间

6

我感觉这是统计缺陷，算子在执行过程中有三个步骤（经典火山模型）：open、next、close。IndexReader在统计执行时间时候是在next时候统计的。但是去tikv请求数据时候是在open阶段就开始了，但是并没有统计到IndexReader里面。如果大结果集执行时间大多都在Next上的时候不太明显，如果想你这种执行的非常快，那么就容易看到子算子的执行时间反而可能比IndexReader还要大。
看我这个大结果集的，看起来就没什么问题。

mysql> explain analyze select L_SHIPDATE from lineitem where L_RECEIPTDATE < now() and L_LINENUMBER > 1;
+----------------------------+-------------+----------+-----------+---------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------+----------+------+
| id                         | estRows     | actRows  | task      | access object                                                       | execution info                                                                                                                                                                                                                                                                                                                                                       | operator info                             | memory   | disk |
+----------------------------+-------------+----------+-----------+---------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------+----------+------+
| Projection_4               | 19973507.81 | 20029587 | root      |                                                                     | time:3.6s, loops:20923, Concurrency:5                                                                                                                                                                                                                                                                                                                                | tpch.lineitem.l_shipdate                  | 193.3 KB | N/A  |
| └─IndexReader_7            | 19973507.81 | 20029587 | root      |                                                                     | time:3.47s, loops:20923, cop_task: {num: 712, max: 248.7ms, min: 548.2µs, avg: 62.2ms, p95: 152.3ms, max_proc_keys: 67552, p95_proc_keys: 67552, tot_proc: 31.4s, tot_wait: 6.28s, rpc_num: 712, rpc_time: 44.3s, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15}                                                                                               | index:Selection_6                         | 4.74 MB  | N/A  |
|   └─Selection_6            | 19973507.81 | 20029587 | cop[tikv] |                                                                     | tikv_task:{proc max:193ms, min:0s, avg: 41.9ms, p80:75ms, p95:116ms, iters:28903, tasks:712}, scan_detail: {total_process_keys: 26706944, total_process_keys_size: 2243383296, total_keys: 26707656, get_snapshot_time: 311.8ms, rocksdb: {key_skipped_count: 26706944, block: {cache_hit_count: 3541, read_count: 24926, read_byte: 147.6 MB, read_time: 156.8ms}}} | gt(tpch.lineitem.l_linenumber, 1)         | N/A      | N/A  |
|     └─IndexRangeScan_5     | 24966884.76 | 26706944 | cop[tikv] | table:lineitem, index:idx2(L_RECEIPTDATE, L_SHIPDATE, L_LINENUMBER) | tikv_task:{proc max:193ms, min:0s, avg: 40.9ms, p80:72ms, p95:115ms, iters:28903, tasks:712}                                                                                                                                                                                                                                                                         | range:[-inf,2023-05-28], keep order:false | N/A      | N/A  |
+----------------------------+-------------+----------+-----------+---------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------+----------+------+
4 rows in set (3.61 sec)
7

感谢，确实有些看起来没问题有些问题很大

8

此话题已在最后回复的 60 天后被自动关闭。不再允许新回复。