Look at this, it’s so slow…
mysql> explain analyze select /*+ read_from_storage(tikv[lineitem]) */ count(*) from lineitem;
+----------------------------+-------------+----------+-----------+----------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+----------------------------+-------------+----------+-----------+----------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------+-----------+------+
| HashAgg_13 | 1.00 | 1 | root | | time:39.4s, loops:2, partial_worker:{wall_time:39.362488482s, concurrency:5, task_num:1, tot_wait:3m16.81108575s, tot_exec:94.27µs, tot_time:3m16.811192801s, max:39.362249552s, p95:39.362249552s}, final_worker:{wall_time:0s, concurrency:5, task_num:1, tot_wait:3m16.811393418s, tot_exec:30.083µs, tot_time:3m16.811426486s, max:39.362296841s, p95:39.362296841s} | funcs:count(Column#18)->Column#17 | 16.5 KB | N/A |
| └─TableReader_14 | 1.00 | 156 | root | | time:39.4s, loops:2, cop_task: {num: 159, max: 7.69s, min: 212.8ms, avg: 3.54s, p95: 7.15s, max_proc_keys: 462798, p95_proc_keys: 462756, tot_proc: 8m47.6s, tot_wait: 33.5s, rpc_num: 159, rpc_time: 9m23.4s, copr_cache_hit_ratio: 0.00, build_task_duration: 274.2µs, max_distsql_concurrency: 15}, backoff{regionMiss: 2ms} | data:HashAgg_6 | 438 Bytes | N/A |
| └─HashAgg_6 | 1.00 | 156 | cop[tikv] | | tikv_task:{proc max:7.2s, min:212ms, avg: 3.32s, p80:5.75s, p95:6.83s, iters:70417, tasks:159}, scan_detail: {total_process_keys: 72080384, total_process_keys_size: 2594893824, total_keys: 73692884, get_snapshot_time: 16.4s, rocksdb: {delete_skipped_count: 130912, key_skipped_count: 73762895, block: {cache_hit_count: 2208, read_count: 455143, read_byte: 4.43 GB, read_time: 5.11s}}} | funcs:count(1)->Column#18 | N/A | N/A |
| └─TableFullScan_12 | 70899712.00 | 72080384 | cop[tikv] | table:lineitem | tikv_task:{proc max:7.2s, min:211ms, avg: 3.32s, p80:5.75s, p95:6.83s, iters:70417, tasks:159} | keep order:false | N/A | N/A |
+----------------------------+-------------+----------+-----------+----------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------+-----------+------+
4 rows in set (39.36 sec)
Main slow points:
- copr_cache_hit_ratio=0, no cache hit on the TiDB side.
- get_snapshot_time: 16.4s, not sure why it’s so slow…
- read_byte: 4.43 GB, read_time: 5.11s, physical read occurred.
- Table scan is slow, my understanding is: time:39.4s - get_snapshot_time: 16.4s - read_time: 5.11s = 17.89s
17.89s * 15 / tasks:159 = 1.69s, pure memory read of data from one region takes an average of 1.69 seconds, feels very slow…
At that time, data was being loaded concurrently, which should be due to insufficient CPU. But why is get_snapshot_time so slow?
Sometimes 15 tasks working together can barely keep up with one task in a traditional database. It feels like the data read and scan efficiency of TiKV is not high.