The first query with the primary key takes a long time, but each stage of the execution plan is very short

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

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

| username: TiDBer_KkruFifg

[TiDB Usage Environment] Production Environment / Testing / Poc
[TiDB Version]
[Reproduction Path] What operations were performed to encounter the issue
[Encountered Issue: Problem Phenomenon and Impact]
[Resource Configuration] Enter TiDB Dashboard - Cluster Info - Hosts and take a screenshot of this page
[Attachments: Screenshots / Logs / Monitoring]

Version Information
v5.1.4

Problem Description
The following SQL query takes 16 seconds on the first run, and approximately 0.16 seconds on subsequent runs. The execution plan and slow logs are shown below.
desc analyze SELECT * FROM aaaa_bbbb_cccccc_tab FORCE INDEX (PRIMARY) WHERE 1 <= id ORDER BY id LIMIT 5000;
Why does this SQL query take so long? According to the execution plan, each stage takes very little time.
From the slow log, the main time consumption is in # PD_total: 15.762042992

Execution Plan

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)

Slow Log 1 as follows

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;

Slow Log 2 as follows

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;

| username: 像风一样的男子 | Original post link

There is a cache

| username: TiDBer_KkruFifg | Original post link

So why is it so slow? Each stage doesn’t seem slow according to the execution plan?

| username: Fly-bird | Original post link

Cached it.

| username: 像风一样的男子 | Original post link

Fetching 5000 records is slow due to the transmission.

| username: tidb菜鸟一只 | Original post link

Try adding SQL_NO_CACHE and test again.

| username: TiDBer_KkruFifg | Original post link

Adding sql_no_cache is still very fast, as shown below:

>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)
| username: 喵父666 | Original post link

There should be caching.

| username: TiDBer_KkruFifg | Original post link

No cache, the execution plan above shows copr_cache_hit_ratio: 0.00
The official explanation for this field is as follows:

| username: Jolyne | Original post link

The first two you posted, the first execution had no cache, but the second one obviously had a cache. The copr_cache_hit_ratio parameter is not zero, which indicates that there was caching.

| username: TiDBer_KkruFifg | Original post link

I added sql_no_cache when executing the SQL as suggested by others, and the execution speed was very fast, with the copr_cache_hit_ratio parameter being 0.

| username: system | Original post link

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.