The cop_task records the time when the cop request occurs on the TiDB side, including tikvclient-grpc request time ↔ network time ↔ tikvServer-grpc processing time ↔ processing time in TiKV.
Looking at actRows here, after being filtered by Selection_10, the number of records passed to the HashAgg_6 operator in TiKV is 0. Therefore, the HashAgg_6 operator did not consume time in this step (because it processed 0 records). The maximum processing time for the sub-operators (Selection_10, TableFullScan_9) on the TiKV side is proc max: 540ms, so the overall maximum processing time for HashAgg_6 is 540ms.
Since the data returned to the TiDB server is 0, I understand that the cop_task max: 2.21s is mainly spent on gRPC here (possibly due to queuing on either the TiDB server side or the TiKV side). Check if there was a large amount of data being transferred from TiKV to TiDB at that time.
Simple scenario simulation:
The current cluster has only one PD, one TiDB, and one TiKV, all on the same machine.
# No pressure on gRPC: concurrent execution of predicate pushdown -> select * from lineitem where year(L_SHIPDATE) > year(L_COMMITDATE) + 1000
mysql> explain analyze select * from nation where n_name='123';
+-------------------------+---------+---------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+---------+---------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| TableReader_8 | 0.00 | 0 | root | | time:598.7µs, loops:1, RU:0.548323, cop_task: {num: 1, max: 530.8µs, proc_keys: 25, tot_proc: 77.7µs, tot_wait: 68.1µs, rpc_num: 1, rpc_time: 508.2µs, copr_cache_hit_ratio: 0.00, build_task_duration: 11.2µs, max_distsql_concurrency: 1} | data:Selection_7 | 241 Bytes | N/A |
| └─Selection_7 | 0.00 | 0 | cop[tikv] | | tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 25, total_process_keys_size: 3109, total_keys: 26, get_snapshot_time: 20µs, rocksdb: {key_skipped_count: 25, block: {}}} | eq(tpch1.nation.n_name, "123") | N/A | N/A |
| └─TableFullScan_6 | 25.00 | 25 | cop[tikv] | table:nation | tikv_task:{time:0s, loops:1} | keep order:false | N/A | N/A |
+-------------------------+---------+---------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
3 rows in set (0.00 sec)
# Pressure on gRPC: concurrent execution without predicate pushdown -> select * from lineitem where TIMESTAMPDIFF(YEAR,L_SHIPDATE,L_COMMITDATE) > 1000
mysql> explain analyze select * from nation where n_name='123';
+-------------------------+---------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+---------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| TableReader_8 | 0.00 | 0 | root | | time:114.9ms, loops:1, RU:0.559090, cop_task: {num: 1, max: 114.8ms, proc_keys: 25, tot_proc: 110µs, tot_wait: 155.7µs, rpc_num: 1, rpc_time: 114.7ms, copr_cache_hit_ratio: 0.00, build_task_duration: 13.3µs, max_distsql_concurrency: 1} | data:Selection_7 | 243 Bytes | N/A |
| └─Selection_7 | 0.00 | 0 | cop[tikv] | | tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 25, total_process_keys_size: 3109, total_keys: 26, get_snapshot_time: 39.9µs, rocksdb: {key_skipped_count: 25, block: {}}} | eq(tpch1.nation.n_name, "123") | N/A | N/A |
| └─TableFullScan_6 | 25.00 | 25 | cop[tikv] | table:nation | tikv_task:{time:0s, loops:1} | keep order:false | N/A | N/A |
+-------------------------+---------+---------+-----------+---------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
3 rows in set (0.12 sec)
You can see that under pressure, gRPC may cause the cop_task time to be long while the tikv_task time is very short. Your issue might be similar to this test.
|
username: h5n1
|
username: