主键第一次查询耗时较长，执行计划每个阶段耗时也很短

TiDBer_KkruFifg · 2023 年10 月 25 日 10:34

【 TiDB 使用环境】生产环境 /测试/ Poc
【 TiDB 版本】
【复现路径】做过哪些操作出现的问题
【遇到的问题：问题现象及影响】
【资源配置】进入到 TiDB Dashboard -集群信息 (Cluster Info) -主机(Hosts) 截图此页面
【附件：截图/日志/监控】


版本信息
v5.1.4

问题描述
下面 sql 第一次查询耗时 16 秒，往后再查大概耗时 0.16 秒，执行计划和慢日志请见下面
desc analyze SELECT * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;
为什么这个sql耗时这么长？从执行计划看，每个阶段耗时都很少
从慢日志来看主要耗时在了 # PD_total: 15.762042992 


执行计划
>desc analyze SELECT * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;
+-----------------------------+---------+---------+-----------+----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
| id                          | estRows | actRows | task      | access object              | execution info                                                                                                                                                                                                            | operator info                   | memory  | disk |
+-----------------------------+---------+---------+-----------+----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
| Limit_12                    | 5000.00 | 5000    | root      |                            | time:24.5ms, loops:6                                                                                                                                                                                                      | offset:0, count:5000            | N/A     | N/A  |
| └─TableReader_22            | 5000.00 | 5000    | root      |                            | time:24.5ms, loops:5, cop_task: {num: 1, max: 22.6ms, proc_keys: 5000, tot_proc: 15ms, tot_wait: 1ms, rpc_num: 1, rpc_time: 22.6ms, copr_cache_hit_ratio: 0.00}                                                           | data:Limit_21                   | 1.67 MB | N/A  |
|   └─Limit_21                | 5000.00 | 5000    | cop[tikv] |                            | tikv_task:{time:11ms, loops:9}, scan_detail: {total_process_keys: 5000, total_keys: 5001, rocksdb: {delete_skipped_count: 0, key_skipped_count: 9998, block: {cache_hit_count: 24, read_count: 41, read_byte: 519.1 KB}}} | offset:0, count:5000            | N/A     | N/A  |
|     └─TableRangeScan_20     | 5000.00 | 5000    | cop[tikv] | table:aaaa_bbbb_cccccc_tab | tikv_task:{time:11ms, loops:9}                                                                                                                                                                                            | range:[1,+inf], keep order:true | N/A     | N/A  |
+-----------------------------+---------+---------+-----------+----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
4 rows in set (16.66 sec)

>desc analyze SELECT * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;
+-----------------------------+---------+---------+-----------+----------------------------+-----------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
| id                          | estRows | actRows | task      | access object              | execution info                                                                                                                    | operator info                   | memory  | disk |
+-----------------------------+---------+---------+-----------+----------------------------+-----------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
| Limit_12                    | 5000.00 | 5000    | root      |                            | time:1.98ms, loops:6                                                                                                              | offset:0, count:5000            | N/A     | N/A  |
| └─TableReader_22            | 5000.00 | 5000    | root      |                            | time:1.97ms, loops:5, cop_task: {num: 1, max: 858.8µs, proc_keys: 0, rpc_num: 1, rpc_time: 846.8µs, copr_cache_hit_ratio: 1.00}   | data:Limit_21                   | 1.67 MB | N/A  |
|   └─Limit_21                | 5000.00 | 5000    | cop[tikv] |                            | tikv_task:{time:11ms, loops:9}                                                                                                    | offset:0, count:5000            | N/A     | N/A  |
|     └─TableRangeScan_20     | 5000.00 | 5000    | cop[tikv] | table:aaaa_bbbb_cccccc_tab | tikv_task:{time:11ms, loops:9}                                                                                                    | range:[1,+inf], keep order:true | N/A     | N/A  |
+-----------------------------+---------+---------+-----------+----------------------------+-----------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
4 rows in set (0.16 sec)

慢日志 1 如下
# Time: 2023-10-25T11:49:42.716679841+08:00
# Txn_start_ts: 445174452335673352
# User@Host: user_1111111[user_1111111] @ 192.168.1.10 [192.168.1.10]
# Conn_ID: 3832913
# Query_time: 16.657547907
# Parse_time: 0.000080919
# Compile_time: 0.000289285
# Rewrite_time: 0.000222468
# Optimize_time: 0.000137673
# Wait_TS: 0.000262141
# Cop_time: 0.024211957 Process_time: 0.015 Wait_time: 0.001 Request_count: 1 Process_keys: 5000 Total_keys: 5001 Rocksdb_key_skipped_count: 9998 Rocksdb_block_cache_hit_count: 24 Rocksdb_block_read_count: 41 Rocksdb_block_read_byte: 531518
# DB: db_name_aaaaaaaaaaaaaaaaaa
# Is_internal: false
# Digest: a71f6770e827e0ca204aeeb0ae2ff68c7d002e3859b71d658dc58dc4a0948d4b
# Num_cop_tasks: 1
# Cop_proc_avg: 0.015 Cop_proc_addr: 192.168.1.22:20160
# Cop_wait_avg: 0.001 Cop_wait_addr: 192.168.1.22:20160
# Mem_max: 1748334
# Prepared: false
# Plan_from_cache: false
# Plan_from_binding: false
# Has_more_results: false
# KV_total: 0.022988492
# PD_total: 15.762042992
# Backoff_total: 0
# Write_sql_response_total: 0.000002919
# Succ: true
# Plan_digest: 5f7131616f66869e9858eca840a8adbec75143761f71f6055f20808ed4d2e955
use db_name_aaaaaaaaaaaaaaaaaa;
desc analyze SELECT * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;

慢日志 2 如下
# Time: 2023-10-25T15:06:28.267985485+08:00
# Txn_start_ts: 445177551401779542
# User@Host: user_1111111[user_1111111] @ 192.168.10.100 [192.168.10.100]
# Conn_ID: 57
# Query_time: 0.18738585
# Parse_time: 0.000072428
# Compile_time: 0.000333638
# Rewrite_time: 0.000260213
# Optimize_time: 0.000129253
# Wait_TS: 0.000135735
# Cop_time: 0.002855655 Wait_time: 0.001 Request_count: 1
# DB: db_name_aaaaaaaaaaaaaaaaaa
# Is_internal: false
# Digest: a71f6770e827e0ca204aeeb0ae2ff68c7d002e3859b71d658dc58dc4a0948d4b
# Num_cop_tasks: 1
# Cop_proc_avg: 0 Cop_proc_addr: 192.168.1.22:20160
# Cop_wait_avg: 0.001 Cop_wait_addr: 192.168.1.22:20160
# Mem_max: 1748295
# Prepared: false
# Plan_from_cache: false
# Plan_from_binding: false
# Has_more_results: false
# KV_total: 0.001454032
# PD_total: 0.000128002
# Backoff_total: 0
# Write_sql_response_total: 0.000003483
# Succ: true
# Plan_digest: 5f7131616f66869e9858eca840a8adbec75143761f71f6055f20808ed4d2e955
desc analyze SELECT * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;

像风一样的男子 · 2023 年10 月 25 日 10:54

有缓存
https://docs.pingcap.com/zh/tidb/stable/coprocessor-cache

TiDBer_KkruFifg · 2023 年10 月 25 日 11:15

那为什么这么慢？从执行计划看各个阶段都不慢？

Fly-bird · 2023 年10 月 26 日 00:03

缓存下来了

像风一样的男子 · 2023 年10 月 26 日 00:10

取5000条记录，慢在传输上了

tidb菜鸟一只 · 2023 年10 月 26 日 00:32

加上sql_no_cache再试一下

TiDBer_KkruFifg · 2023 年10 月 26 日 00:55

加上 sql_no_cache 还是很快，如下

>desc analyze SELECT sql_no_cache * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;
+-----------------------------+---------+---------+-----------+----------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
| id                          | estRows | actRows | task      | access object              | execution info                                                                                                                                                                                                         | operator info                   | memory  | disk |
+-----------------------------+---------+---------+-----------+----------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
| Limit_12                    | 5000.00 | 5000    | root      |                            | time:13.9ms, loops:6                                                                                                                                                                                                   | offset:0, count:5000            | N/A     | N/A  |
| └─TableReader_22            | 5000.00 | 5000    | root      |                            | time:13.9ms, loops:5, cop_task: {num: 1, max: 12.9ms, proc_keys: 5000, tot_proc: 9ms, rpc_num: 1, rpc_time: 12.9ms, copr_cache_hit_ratio: 0.00}                                                                        | data:Limit_21                   | 1.67 MB | N/A  |
|   └─Limit_21                | 5000.00 | 5000    | cop[tikv] |                            | tikv_task:{time:7ms, loops:9}, scan_detail: {total_process_keys: 5000, total_keys: 5001, rocksdb: {delete_skipped_count: 0, key_skipped_count: 9998, block: {cache_hit_count: 52, read_count: 0, read_byte: 0 Bytes}}} | offset:0, count:5000            | N/A     | N/A  |
|     └─TableRangeScan_20     | 5000.00 | 5000    | cop[tikv] | table:aaaa_bbbb_cccccc_tab | tikv_task:{time:7ms, loops:9}                                                                                                                                                                                          | range:[1,+inf], keep order:true | N/A     | N/A  |
+-----------------------------+---------+---------+-----------+----------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+---------+------+
4 rows in set (0.25 sec)

喵父666 · 2023 年10 月 26 日 01:43

应该是有缓存

TiDBer_KkruFifg · 2023 年10 月 26 日 02:02

没缓存，上面执行计划里显示 copr_cache_hit_ratio: 0.00
官网对这个字段的解释如下
https://docs.pingcap.com/zh/tidb/stable/coprocessor-cache

Jolyne · 2023 年10 月 26 日 02:24

你一开始发的两个，第一次执行没有缓存，第二次明显有缓存啊，这个 copr_cache_hit_ratio参数不为0，说明有缓存了

TiDBer_KkruFifg · 2023 年10 月 26 日 02:30

我在下面按照其他建议执行sql时加了 sql_no_cache ，然后执行速度很快，且 copr_cache_hit_ratio 参数为 0

system · 2023 年12 月 25 日 02:31

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