Why did MAX() take 100ms while MIN() took 8 seconds?<\/li>\n<\/ul>\n\n\n\nPlease note that developers sourced most execution plans in the following cases from production environments (desensitized for privacy).<\/p>\n\n\n\n
Query Latency Jitter<\/h3>\n\n\n\n Intermittent query latency jitter is one of the most common performance issues. If the slow query log can pinpoint the specific SQL statements causing performance fluctuations, further analysis of their operator execution information often reveals the root cause and provides actionable optimization clues.<\/p>\n\n\n\n
Case<\/h4>\n\n\n\n Consider a customer\u2019s point query latency jitter issue, where delays occasionally exceeded 2 seconds. Using the slow query log, we located the operator execution metrics for one such problematic query:<\/p>\n\n\n\n
mysql> explain analyze select * from t0 where col0 = 100 and col1 = 'A';\n+---------------------+---------+---------+-----------+---------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------+---------+------+\n| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |\n+---------------------+---------+---------+-----------+---------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------+---------------+---------+------+\n| Point_Get_1 | 1 | 1 | root | table:t0, index:uniq_col0_col1 | time:2.52s, loops:2, ResolveLock:{num_rpc:1, total_time:2.52s}, Get:{num_rpc:3, total_time:2.2ms}, txnNotFound_backoff:{num:12, total_time:2.51s}, tikv_wall_time: 322.8us, scan_detail: {total_process_keys: 2, total_process_keys_size: 825, total_keys: 9, get_snapshot_time: 18us, rocksdb: {delete_skipped_count: 3, key_skipped_count: 14, block: {cache_hit_count: 16}}} | N\/A | N\/A | N\/A |\n+---------------------+---------+---------+-----------+---------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------+---------------+---------+------+<\/code><\/pre>\n\n\n\nAnalysis<\/h4>\n\n\n\n First, we observe that the query involves only a Point_Get_1 <\/code>operator, with an execution time of 2.52s<\/strong> recorded in execution info<\/strong>. <\/strong>This indicates that the entire execution duration is captured accurately.<\/p>\n\n\n\nUpon closer inspection of the execution info<\/strong>, we note the presence of a ResolveLock <\/strong>entry. Details reveal that this operation consumed 2.52s<\/strong> in total, meaning nearly all query time was spent resolving locks. In contrast, the actual Get <\/strong>operation took only 2.2ms<\/strong>, confirming that data access was negligible.<\/p>\n\n\n\nAdditionally, a txnNotFound_backoff <\/strong>entry highlights retries triggered by stale transactions. Specifically, 12 retries<\/strong> occurred, cumulatively lasting 2.51s<\/strong> (aligning closely with the ResolveLock<\/code> duration of 2.52s<\/strong>). <\/p>\n\n\n\nThis leads us to hypothesize: the point query likely encountered locks from stale transactions. During the ResolveLock<\/strong> phase, the system detected expired locks, initiating a cleanup process. This lock resolution overhead caused high query latency.<\/strong><\/p>\n\n\n\nTo validate this hypothesis, we can cross-reference monitoring data, as shown in the below image: <\/p>\n\n\n\nOperator Concurrency in TiDB<\/h3>\n\n\n\n In TiDB, we can adjust the execution concurrency of operators through system variables to ultimately tune SQL performance. Operator concurrency significantly impacts execution efficiency. For example, with the same number of coprocessor tasks, increasing concurrency from 5 to 10 may nearly double performance\u2014though at the cost of higher resource utilization. Execution information helps us understand the actual concurrency of operators, laying the groundwork for deeper performance diagnostics. Let\u2019s examine a real-world case.<\/p>\n\n\n\n
Case<\/h4>\n\n\n\n The system was configured with: <\/p>\n\n\n\n
\ntidb_executor_concurrency<\/code> = 5 <\/li>\n\n\n\ntidb_distsql_scan_concurrency<\/code> = 15 <\/li>\n<\/ul>\n\n\n\nWhat are the actual execution concurrencies for the cop_task<\/code> and tikv_task<\/code> in the following execution plan? <\/p>\n\n\n\nmysql> explain analyze select * from t0 where c like '2147%';\n+-------------------------------+---------+---------+-----------+-------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+---------+------+\n| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |\n+-------------------------------+---------+---------+-----------+-------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+---------+------+\n| IndexLookUp_10 | 3.82 | 99 | root | | time:2.83ms, loops:2, index_task: {total_time: 733.8\u00b5s, fetch_handle: 727.9\u00b5s, build: 806ns, wait: 5.14\u00b5s}, table_task: {total_time: 1.96ms, num: 1, concurrency: 5}, next: {wait_index: 821\u00b5s, wait_table_lookup_build: 108.2\u00b5s, wait_table_lookup_resp: 1.85ms} | | 41.0 KB | N\/A |\n| \u251c\u2500IndexRangeScan_8(Build) | 3.82 | 99 | cop[tikv] | table:t0, index:idx_c(c) | time:719.1\u00b5s, loops:3, cop_task: {num: 1, max: 650\u00b5s, proc_keys: 99, rpc_num: 1, rpc_time: 625.7\u00b5s, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15}, tikv_task:{time:0s, loops:3}, scan_detail: {total_process_keys: 99, total_process_keys_size: 18810, total_keys: 100, get_snapshot_time: 102\u00b5s, rocksdb: {key_skipped_count: 99, block: {cache_hit_count: 3}}} | range:[\"2147\",\"2148\"), keep order:false | N\/A | N\/A |\n| \u2514\u2500TableRowIDScan_9(Probe) | 3.82 | 99 | cop[tikv] | table:t0 | time:1.83ms, loops:2, cop_task: {num: 4, max: 736.9\u00b5s, min: 532.6\u00b5s, avg: 599\u00b5s, p95: 736.9\u00b5s, max_proc_keys: 44, p95_proc_keys: 44, rpc_num: 4, rpc_time: 2.32ms, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15}, tikv_task:{proc max:0s, min:0s, avg: 0s, p80:0s, p95:0s, iters:5, tasks:4}, scan_detail: {total_process_keys: 99, total_process_keys_size: 22176, total_keys: 99, get_snapshot_time: 217.3\u00b5s, rocksdb: {block: {cache_hit_count: 201}}} | keep order:false | N\/A | N\/A |\n+-------------------------------+---------+---------+-----------+-------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+---------+------+\n3 rows in set (0.00 sec)<\/code><\/pre>\n\n\n\nAnalysis<\/h4>\n\n\n\n We just used this example to explain the relationship between cop_task and tikv_task items in the execution information and the actual execution concurrency of the cop task.<\/p>\n\n\n\n
Cop_task vs tikv_task<\/h5>\n\n\n\n First, it\u2019s critical to clarify that the xxx_task<\/strong> entries in execution info<\/strong> are not equivalent to the “task<\/strong>” column in execution plans.<\/p>\n\n\n\nFor example, in the execution plan, the category of the task <\/strong>column is “root” <\/strong>, “cop [tikv]” <\/strong>, etc. It describes which component the operator actually executes in (such as TiDB, TiKV, or TiFlash). Additionally, it further explains its communication protocol type with the storage engine (such as Coprocessor, Batch Coprocessor, or MPP).<\/p>\n\n\n\nIn contrast, the various tasks <\/strong>in execution info <\/strong>are more about breaking down operator execution information from different dimensions. This allows users to quickly locate potential performance issues and verify each other through information from different dimensions. Specifically:<\/p>\n\n\n\n\ntikv_task<\/strong> describes the overall execution of a specific TiKV operator;<\/li>\n\n\n\ncop_task<\/strong> describes the execution of the entire RPC task, which includes tikv_task <\/strong>. For example, a cop_task <\/strong>may contain two operators, tableScan + Selection<\/strong>. Each operator has its own tikv_task <\/strong>information to describe its execution. cop_task <\/strong>describes the execution information of the entire RPC request, which covers the execution time of these two operators.<\/li>\n<\/ul>\n\n\n\nSimilarly, in an MPP query, the tiflash_task <\/strong>statistic in execution info <\/strong>describes the overall execution of a particular TiFlash operator:<\/p>\n\n\n\n+------------------------------+-------------+----------+--------------+----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------+-----------+---------+\n| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |\n+------------------------------+-------------+----------+--------------+----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------+-----------+---------+\n| HashAgg_22 | 1.00 | 1 | root | | time:17ms, open:1.92ms, close:4.83\u00b5s, loops:2, RU:1832.08, partial_worker:{wall_time:15.055084ms, concurrency:5, task_num:1, tot_wait:15.017625ms, tot_exec:12.333\u00b5s, tot_time:75.203959ms, max:15.042667ms, p95:15.042667ms}, final_worker:{wall_time:15.079958ms, concurrency:5, task_num:5, tot_wait:1.414\u00b5s, tot_exec:41ns, tot_time:75.277708ms, max:15.060375ms, p95:15.060375ms} | funcs:count(Column#19)->Column#17 | 6.23 KB | 0 Bytes |\n| \u2514\u2500TableReader_24 | 1.00 | 1 | root | | time:16.9ms, open:1.9ms, close:3.46\u00b5s, loops:2, cop_task: {num: 2, max: 0s, min: 0s, avg: 0s, p95: 0s, copr_cache_hit_ratio: 0.00} | MppVersion: 3, data:ExchangeSender_23 | 673 Bytes | N\/A |\n| \u2514\u2500ExchangeSender_23 | 1.00 | 1 | mpp[tiflash] | | tiflash_task:{time:13.1ms, loops:1, threads:1}, tiflash_network: {inner_zone_send_bytes: 24} | ExchangeType: PassThrough | N\/A | N\/A |\n| \u2514\u2500HashAgg_9 | 1.00 | 1 | mpp[tiflash] | | tiflash_task:{time:13.1ms, loops:1, threads:1} | funcs:count(test.lineitem.L_RETURNFLAG)->Column#19 | N\/A | N\/A |\n| \u2514\u2500TableFullScan_21 | 11997996.00 | 11997996 | mpp[tiflash] | table:lineitem | tiflash_task:{time:12.8ms, loops:193, threads:12}, tiflash_scan:{mvcc_input_rows:0, mvcc_input_bytes:0, mvcc_output_rows:0, local_regions:10, remote_regions:0, tot_learner_read:0ms, region_balance:{instance_num: 1, max\/min: 10\/10=1.000000}, delta_rows:0, delta_bytes:0, segments:20, stale_read_regions:0, tot_build_snapshot:0ms, tot_build_bitmap:0ms, tot_build_inputstream:15ms, min_local_stream:10ms, max_local_stream:11ms, dtfile:{data_scanned_rows:11997996, data_skipped_rows:0, mvcc_scanned_rows:0, mvcc_skipped_rows:0, lm_filter_scanned_rows:0, lm_filter_skipped_rows:0, tot_rs_index_check:3ms, tot_read:53ms}} | keep order:false | N\/A | N\/A |\n+------------------------------+-------------+----------+--------------+----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------+-----------+---------+<\/code><\/pre>\n\n\n\nExecution Concurrency of Cop Task<\/h5>\n\n\n\n First, let’s examine the execution plan. IndexLookUp_10 <\/code>is a root operator <\/strong>. We know that the IndexLookUp <\/code>operator mainly performs two steps: one is to obtain the row id <\/strong>of the target row through the index; the other is to read the required column data according to the rowid. In IndexLookUp_10 <\/code>‘s execution info <\/strong>, the details of index_task <\/code>and table_task<\/code> are listed separately. Obviously, index_task <\/code>corresponds to the IndexRangeScan_8 <\/code>operator, and table_task <\/code>corresponds to the TableRowIDScan_9 <\/code>operator.<\/p>\n\n\n\nFrom the perspective of concurrency, index_task <\/code>does not display concurrency information, which means that the concurrency of the IndexRangeScan_8 <\/code>operator defaults to 1 <\/strong>. However, the cop_task <\/strong>of the IndexRangeScan_8 <\/code>is 15 <\/strong>(determined by the tidb_distsql_scan_concurrency<\/code> parameter), which means that theoretically it can execute 15 cop tasks <\/strong>concurrently to read data.<\/p>\n\n\n\nFor table_task<\/code>, its concurrency is 5 <\/strong>(determined by the tidb_executor_concurrency<\/code> parameter), which means that up to 5 TableRowIDScan_9 <\/code>operators <\/strong>can run simultaneously. The distsql_concurrency <\/code>of TableRowIDScan_9 <\/code>cop_task <\/strong>is also 15 <\/strong>(determined by tidb_distsql_scan_concurrency <\/code>). Therefore, the maximum concurrent read capacity of table_task<\/code> is 5 \u00d7 15 = 75 cop tasks<\/strong>.<\/p>\n\n\n\nMax => Min, 100ms => 8s<\/h3>\n\n\n\n A SQL query calculating the max value of an indexed column took approximately 100 milliseconds. However, when modified to calculate the min value, execution time soared to 8+ seconds. Below is the `EXPLAIN ANALYZE` output for both scenarios:<\/p>\n\n\n\n
mysql> explain analyze select max(time_a) from t0 limit 1;\n+--------------------------------+---------+---------+-----------+----------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------+------+\n| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |\n+--------------------------------+---------+---------+-----------+----------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------+------+\n| Limit_14 | 1.00. | 1 | root | | time:2.328901ms, loops:2 | offset:0, count:1 | N\/A | N\/A | \n| \u2514\u2500StreamAgg_19 | 1.00 | 1 | root | | time:2.328897ms, loops:1 | funcs:max(t0.time_a)->Column#18 | 128 Bytes | N\/A |\n| \u2514\u2500Limit_39 | 1.00 | 1 | root | | time:2.324137ms, loops:2 | offset:0, count:1 | N\/A | N\/A |\n| \u2514\u2500IndexReader_45 | 1.00 | 1 | root | | time:2.322215ms, loops:1, cop_task: {num: 1, max:2.231389ms, proc_keys: 32, rpc_num: 1, rpc_time: 2.221023ms, copr_cache_hit_ratio: 0.00} | index:Limit_26 | 461 Bytes | N\/A |\n| \u2514\u2500Limit_44 | 1.00 | 1 | cop[tikv] | | time:0ns, loops:0, tikv_task:{time:2ms, loops:1} | offset:0, count:1 | N\/A | N\/A |\n| \u2514\u2500IndexFullScan_31 | 1.00 | 32 | cop[tikv] | table:t0, index:time_a(time_a) | time:0ns, loops:0, tikv_task:{time:2ms, loops:1} | keep order:true, desc | N\/A | N\/A |\n+------------------------------+---------+---------+-----------+----------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------+------+\n6 rows in set (0.12 sec)\n\nmysql> explain analyze select min(time_a) from t0 limit 1;\n+--------------------------------+---------+---------+-----------+----------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------------+------+\n| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |\n+--------------------------------+---------+---------+-----------+----------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------------+------+\n| Limit_14 | 1.00 | 1 | root | | time:8.263857153s, loops:2 | offset:0, count:1 | N\/A | N\/A |\n| \u2514\u2500StreamAgg_19 | 1.00 | 1 | root | | time:8.26385598s, loops:1 | funcs:min(t0.time_a)->Column#18 | 128 Bytes | N\/A |\n| \u2514\u2500Limit_39 | 1.00 | 1 | root | | time:8.263848289s, loops:2 | offset:0, count:1 | N\/A | N\/A |\n| \u2514\u2500IndexReader_45 | 1.00 | 1 | root | | time:8.26384652s, loops:1, cop_task: {num: 175, max: 1.955114915s, min: 737.989\u03bcs, avg: 603.631575ms, p95: 1.161411687s, max_proc_keys: 480000, p95_proc_keys: 480000, tot_proc: 1m44.809s, tot_wait: 361ms, rpc_num: 175, rpc_time: 1m45.632904647s, copr_cache_hit_ratio: 0.00} | index:Limit_44 | 6.6025390625 KB | N\/A |\n| \u2514\u2500Limit_44 | 1.00 | 1 | cop[tikv] | | time:0ns, loops:0, tikv_task:{proc max:1.955s, min:0s, p80:784ms, p95:1.118s, iters:175, tasks:175} | offset:0, count:1 | N\/A | N\/A |\n| \u2514\u2500IndexFullScan_31 | 1.00 | 32 | cop[tikv] | table:t0, index:time_a(time_a) | time:0ns, loops:0, tikv_task:{proc max:1.955s, min:0s, p80:784ms, p95:1.118s, iters:175, tasks:175} | keep order:true | N\/A | N\/A |\n+--------------------------------+---------+---------+-----------+----------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------------+------+\n6 rows in set (8.38 sec)<\/code><\/pre>\n\n\n\nAnalysis<\/h4>\n\n\n\n When using operator execution information for performance diagnosis, we generally first look at the execution time of each operator itself (excluding the time spent waiting for operator data) from top to bottom, and then look for the operator that has the greatest impact on the overall query performance. The following is the calculation method for operator execution time.<\/p>\n\n\n\n
Operator Execution Time of Monad Operator<\/h5>\n\n\n\n The following are the execution time calculation methods for different types of operators:<\/p>\n\n\n\n
1. Operator of type “root”<\/strong><\/p>\n\n\n\nYou can directly subtract the execution time of an operator\u2019s sub-operators from its total execution time to obtain the operator\u2019s own processing time.<\/p>\n\n\n\n
2. Operators of type “cop [<\/strong>tikv<\/strong>]”<\/strong><\/p>\n\n\n\nExecution information contains tikv_task <\/code>statistics. Execution time with wait operator data can be estimated using the following formula: Estimated execution time = avg \u00d7 tasks\/concurrency<\/code>. Then, subtract the execution time of the sub-operator from this time to obtain the actual processing time of the operator.<\/p>\n\n\n\n3. Operators of type “mpp [<\/strong>tiflash<\/strong>]”, “cop [tiflash]” or “batchcop [tiflash]”<\/strong><\/p>\n\n\n\nThe execution information contains tiflash_task <\/code>statistics. Usually, proc max <\/code>can be subtracted from the proc max <\/code>of the sub-operator to get the processing time of the operator. This is because all TiFlash tasks for the same query typically start executing at the same time.<\/p>\n\n\n\nNote <\/strong>: For the ExchangeSender<\/code> operator, its execution time includes the time it takes for data to be received by the upper ExchangeReceiver <\/code>operator, so it is often longer than the time it takes for the upper ExchangeReceiver<\/code> to read memory data.<\/p>\n\n\n\nOperator Execution Time of Multi-Operator<\/h5>\n\n\n\n For composite operators with multiple sub-operators, the execution info <\/strong>usually lists the execution information of each sub-operator in detail. For example, in the execution information of the IndexLookUp <\/code>operator, the execution details of index_task <\/code>and table_task <\/code>are explicitly included. By analyzing the execution information of these sub-operators, we can accurately determine which sub-operator has a greater impact on the overall performance, so as to optimize in a more targeted way.<\/p>\n\n\n\nIn this example, we can see that IndexReader_45 <\/code>is the key operator with the greatest impact on performance. Comparing its execution information, it can be found that there is a significant difference in the number of cop tasks<\/code>: in the “max” scenario, there is only one <\/strong>cop task<\/code>; while in the “min” scenario, there are 175 <\/strong>cop tasks<\/code>. At the same time, the number of proc_keys <\/code>has also increased from 32 <\/strong>to 480,000<\/strong>.<\/p>\n\n\n\nJudging from the tags in the “operator info” column, the reading order in the “max” scenario is in descending order ( keep order, desc <\/code>), that is, reading from large to small; while in the “min” scenario, it is the default ascending order ( keep order <\/code>). The optimizer has optimized the reading order of the index according to the type of aggregation function – using descending reading in the “max” scenario and ascending reading in the “min” scenario. The original intention of this optimization strategy is to find the first data that meets the condition as soon as possible.<\/p>\n\n\n\nIn the “min” scenario, there are a large number of deleted but uncollected keys near the smallest keys. Therefore, the system has to scan a large amount of useless data during the reading process until it finds the first valid data, which leads to significant performance overhead.<\/p>\n\n\n\n
![\"Figuring](\"https:\/\/static.pingcap.com\/files\/2025\/07\/25145715\/image-7.png\")
<\/figure>\n\n\n\n