Simple queries occasionally become very slow, want to know where the slowness is

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

Original topic: 简单查询偶尔会变的很慢,想知道慢在哪里

| username: dba-kit

SQL is relatively simple, and after simplification, it is as follows (the date field has an index). Normally, the query takes only a few tens of milliseconds, but every one or two weeks, a query timeout occurs. The SQL is as follows:

SELECT col1, col2
FROM
 t1
WHERE
  (
    date = '2023-12-12'
    AND col2 < -0.01
  );

The screenshot of the failed SQL information at that time is as follows, all times are very low, but the total time is very long:

The statistics are as follows:

	id                         	task     	estRows	operator info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              	actRows	execution info                                                                                                                                                                                                                                                                                                                                                                                                	memory 	disk
	Projection_4               	root     	1.29   		0      	time:10.1s, loops:1, Concurrency:OFF                                                                                                                                                                                                                                                                                                                                                                          	16.9 KB	N/A
	└─IndexLookUp_11           	root     	1.29   	                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           	0      	time:10.1s, loops:1, index_task: {total_time: 6.31ms, fetch_handle: 6.31ms, build: 1.32µs, wait: 6.1µs}, table_task: {total_time: 20.1s, num: 2, concurrency: 20}                                                                                                                                                                                                                                           	24 KB  	N/A
	  ├─IndexRangeScan_8(Build)	cop[tikv]	531.07 	table:t1, index:idx_record_date(record_date), range:[2023-12-12,2023-12-12], keep order:false                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                      	1241   	time:6.23ms, loops:4, cop_task: {num: 1, max: 6.15ms, proc_keys: 1241, tot_proc: 1ms, tot_wait: 3ms, rpc_num: 1, rpc_time: 6.13ms, copr_cache_hit_ratio: 0.00, distsql_concurrency: 50}, tikv_task:{time:4ms, loops:6}, scan_detail: {total_process_keys: 1241, total_process_keys_size: 57086, total_keys: 1242, get_snapshot_time: 3.35ms, rocksdb: {key_skipped_count: 1241, block: {cache_hit_count: 18}}}	N/A    	N/A
	  └─Selection_10(Probe)    	cop[tikv]	1.29   	lt(t1.return_week, -0.01)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               	0      	time:20.1s, loops:2                                                                                                                                                                                                                                                                                                                                                                                           	N/A    	N/A
	    └─TableRowIDScan_9     	cop[tikv]	531.07 	table:t1, keep order:false                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         	0      	                                                                                                                                                                                                                                                                                                                                                                                                              	N/A    	N/A

At that time (2023-12-12 09:33), the TiKV load of the cluster was indeed high. There were many slow queries on this TiDB node, but its own CPU was not high, and the calculations should have been completed in TiKV.


My question is: Since the TiKV load is high, why is the “Coprocessor execution time” phase very short in the total time, and other phases are also very short, but the total time is very long? Where exactly is the slowness?

| username: dba-kit | Original post link

Currently, there are two suspected parameters:

  1. tidb_distsql_scan_concurrency, the default value is 15, and it has been adjusted to 50 online.

  2. token-limit, the default value is 1000. However, looking at the monitoring, the value of get token duration is very small.

| username: dba远航 | Original post link

We have encountered similar issues in production. It is recommended to first investigate from a business perspective to see if there is a regular pattern of large data entries or data modifications during this time period, which could cause outdated statistics and slow SQL execution. If the business aspect is ruled out, then proceed to check the database.

| username: dba-kit | Original post link

This table only inserts 3 records per day, and then it’s all SELECT requests. The execution plan also uses the correct index, so it shouldn’t be a business issue causing this.

| username: 托马斯滑板鞋 | Original post link

:joy: Is there a CPU monitor for the host? I feel that the concurrency is set too high, and at that point in time, there are large SQL queries contending for the CPU, leading to insufficient CPU resources (I still can’t understand this percentage in TiDB).

| username: 小龙虾爱大龙虾 | Original post link

Check the overall resource situation of the cluster during the problem period, and then check the network traffic between clusters during the problem period.