Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

*: Add table scan details logging; change default logging level to "info" (#8616) #8629

Merged
merged 10 commits into from
Jan 6, 2024
Merged

*: Add table scan details logging; change default logging level to "info" (#8616) #8629

merged 10 commits into from
Jan 6, 2024

Conversation

ti-chi-bot
Copy link
Member

@ti-chi-bot ti-chi-bot commented Dec 29, 2023 •
edited by JaySon-Huang
Loading

This is an automated cherry-pick of #8616

What problem does this PR solve?

Issue Number: close #8563

Problem Summary:

What is changed and how it works?

  • Change the default log level to "INFO"
  • Adjust some logging about SegmentReadTaskScheduler UnorderedInputStream
  • Add more details about TableScan
    • num columns, segments, tasks involve
    • delta layer stats
    • mvcc filter stats
    • late materialize filter stats

Check List

Tests

chbenchmark 1500

-- with late materialization
set tidb_opt_enable_late_materialization=1;
explain analyze select   ol_number,          sum(ol_quantity) as sum_qty,          sum(ol_amount) as sum_amount,          avg(ol_quantity) as avg_qty,          avg(ol_amount) as avg_amount,          min(ol_delivery_d) as min_deliver_d,          max(ol_delivery_d) as min_deliver_d,          sum(length(ol_dist_info)),          sum(ol_i_id),max(ol_o_id),max(ol_d_id),max(ol_w_id),sum(ol_number),          count(*) as count_order from     order_line where    ol_delivery_d > '2007-01-02 00:00:00.000000' group by ol_number order by ol_number;
+--------------------------------------+--------------+-----------+--------------+------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| id                                   | estRows      | actRows   | task         | access object    | execution info                                                                                                                                                                                       | operator info                                                                                                                                                                                                                                                                                                                                  | memory    | disk    |
+--------------------------------------+--------------+-----------+--------------+------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| Sort_6                               | 10.67        | 15        | root         |                  | time:3.23s, loops:2, RU:0.000000                                                                                                                                                                                       | chbenchmark.order_line.ol_number                                                                                                                                                                                                                                                                                                                                  | 12.5 KB   | 0 Bytes |
| └─TableReader_54                     | 10.67        | 15        | root         |                  | time:3.23s, loops:2, cop_task: {num: 14, max: 0s, min: 0s, avg: 0s, p95: 0s, copr_cache_hit_ratio: 0.00}                                                                                                                                                                                       | MppVersion: 2, data:ExchangeSender_53                                                                                                                                                                                                                                                                                                                                  | 923 Bytes | N/A     |
|   └─ExchangeSender_53                | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:13, threads:36}                                                                                                                                                                                       | ExchangeType: PassThrough                                                                                                                                                                                                                                                                                                                                  | N/A       | N/A     |
|     └─Projection_9                   | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:13, threads:36}                                                                                                                                                                                       | chbenchmark.order_line.ol_number, Column#12, Column#13, Column#14, Column#15, Column#16, Column#17, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24                                                                                                                                                                                                                                                                                                                                  | N/A       | N/A     |
|       └─Projection_49                | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:13, threads:36}                                                                                                                                                                                       | Column#12, Column#13, div(Column#14, cast(case(eq(Column#79, 0), 1, Column#79), decimal(20,0) BINARY))->Column#14, div(Column#15, cast(case(eq(Column#80, 0), 1, Column#80), decimal(20,0) BINARY))->Column#15, Column#16, Column#17, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24, chbenchmark.order_line.ol_number                                                                                                                                                                  | N/A       | N/A     |
|         └─HashAgg_50                 | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:13, threads:36}                                                                                                                                                                                       | group by:chbenchmark.order_line.ol_number, funcs:sum(Column#81)->Column#12, funcs:sum(Column#82)->Column#13, funcs:sum(Column#83)->Column#79, funcs:sum(Column#84)->Column#14, funcs:sum(Column#85)->Column#80, funcs:sum(Column#86)->Column#15, funcs:min(Column#87)->Column#16, funcs:max(Column#88)->Column#17, funcs:sum(Column#89)->Column#18, funcs:sum(Column#90)->Column#19, funcs:max(Column#91)->Column#20, funcs:max(Column#92)->Column#21, funcs:max(Column#93)->Column#22, funcs:sum(Column#94)->Col... | N/A       | N/A     |
|           └─ExchangeReceiver_52      | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:13, threads:36}                                                                                                                                                                                       | stream_count: 36                                                                                                                                                                                                                                                                                                                                  | N/A       | N/A     |
|             └─ExchangeSender_51      | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:1, threads:1}                                                                                                                                                                                       | ExchangeType: HashPartition, Compression: FAST, Hash Cols: [name: chbenchmark.order_line.ol_number, collate: binary], stream_count: 36                                                                                                                                                                                                                                                                                                                                  | N/A       | N/A     |
|               └─HashAgg_47           | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.21s, loops:1, threads:1}                                                                                                                                                                                       | group by:Column#111, funcs:sum(Column#97)->Column#81, funcs:sum(Column#98)->Column#82, funcs:count(Column#99)->Column#83, funcs:sum(Column#100)->Column#84, funcs:count(Column#101)->Column#85, funcs:sum(Column#102)->Column#86, funcs:min(Column#103)->Column#87, funcs:max(Column#104)->Column#88, funcs:sum(Column#105)->Column#89, funcs:sum(Column#106)->Column#90, funcs:max(Column#107)->Column#91, funcs:max(Column#108)->Column#92, funcs:max(Column#109)->Column#93, funcs:sum(Column#110)->Column#94,... | N/A       | N/A     |
|                 └─Projection_57      | 320161490.84 | 321641463 | mpp[tiflash] |                  | tiflash_task:{time:2.69s, loops:11994, threads:72}                                                                                                                                                                                       | cast(chbenchmark.order_line.ol_quantity, decimal(10,0) BINARY)->Column#97, chbenchmark.order_line.ol_amount->Column#98, chbenchmark.order_line.ol_quantity->Column#99, cast(chbenchmark.order_line.ol_quantity, decimal(10,0) BINARY)->Column#100, chbenchmark.order_line.ol_amount->Column#101, chbenchmark.order_line.ol_amount->Column#102, chbenchmark.order_line.ol_delivery_d->Column#103, chbenchmark.order_line.ol_delivery_d->Column#104, cast(length(chbenchmark.order_line.ol_dist_info), decimal(20,0... | N/A       | N/A     |
|                   └─TableFullScan_35 | 320161490.84 | 321641463 | mpp[tiflash] | table:order_line | tiflash_task:{time:2.18s, loops:11994, threads:72}, tiflash_scan:{dtfile:{total_scanned_packs:234864, total_skipped_packs:9668, total_scanned_rows:1916326703, total_skipped_rows:78937719, total_rs_index_check_time: 634ms, total_read_time: 63607ms, total_disagg_read_cache_hit_size: 0, total_disagg_read_cache_miss_size: 0}, total_create_snapshot_time: 3ms, total_local_region_num: 589, total_remote_region_num: 0, total_learner_read_time: 12ms} | pushed down filter:gt(chbenchmark.order_line.ol_delivery_d, 2007-01-02 00:00:00.000000), keep order:false                                                                                                                                                                                                                                                                                                                                                                                                            | N/A       | N/A     |
+--------------------------------------+--------------+-----------+--------------+------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+

[2023/12/29 00:40:41.829 +08:00] [INFO] [MPPTaskStatistics.cpp:138] ["{\"query_tso\":446636133861556226,\"task_id\":1,\"is_root\":false,\"sender_executor_id\":\"ExchangeSender_51\",\"executors\":[{\"id\":\"ExchangeSender_51\",\"type\":\"ExchangeSender\",\"children\":[\"HashAgg_47\"],\"outbound_rows\":15,\"outbound_blocks\":1,\"outbound_bytes\":2700,\"outbound_allocated_bytes\":6054,\"concurrency\":1,\"execution_time_ns\":3183997226,\"partition_num\":1,\"sender_target_task_ids\":[2],\"exchange_type\":\"Hash\",\"connection_details\":[{\"tunnel_id\":\"tunnel1+2\",\"sender_target_task_id\":2,\"sender_target_host\":\"10.2.12.81:9520\",\"is_local\":true,\"packets\":1,\"bytes\":26377}]},{\"id\":\"HashAgg_47\",\"type\":\"Agg\",\"children\":[\"Projection_57\"],\"outbound_rows\":15,\"outbound_blocks\":1,\"outbound_bytes\":2625,\"outbound_allocated_bytes\":5824,\"concurrency\":1,\"execution_time_ns\":3181997228},{\"id\":\"Projection_57\",\"type\":\"Projection\",\"children\":[\"TableFullScan_35\"],\"outbound_rows\":321641463,\"outbound_blocks\":11994,\"outbound_bytes\":24766392651,\"outbound_allocated_bytes\":28815589970,\"concurrency\":72,\"execution_time_ns\":2661997681},{\"id\":\"TableFullScan_35\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":321641463,\"outbound_blocks\":11994,\"outbound_bytes\":23479826799,\"outbound_allocated_bytes\":32900678464,\"concurrency\":72,\"execution_time_ns\":2156998119,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":23479826799},{\"is_local\":false,\"packets\":0,\"bytes\":0}],\"scan_details\":{\"build_bitmap_time\":\"107084.878ms\",\"create_snapshot_time\":\"3.113ms\",\"create_stream_time\":\"129335.426ms\",\"delta_bytes\":638315925,\"delta_rows\":6719115,\"disagg_cache_hit_size\":0,\"disagg_cache_miss_size\":0,\"dmfile_read_time\":\"63607.359ms\",\"dmfile_scan_rows\":1916326703,\"dmfile_skip_rows\":78937719,\"late_materialization_skip_rows\":12677929,\"learner_read_time\":\"12.917ms\",\"local_region_num\":0,\"mvcc_input_bytes\":7888726886,\"mvcc_input_rows\":464042758,\"mvcc_skip_rows\":6653709,\"num_columns\":9,\"num_read_tasks\":587,\"num_segments\":587,\"read_bytes\":42982171024,\"read_mode\":\"Bitmap\",\"remote_region_num\":0}}],\"host\":\"10.2.12.81:9520\",\"task_init_timestamp\":1703781638606437000,\"task_start_timestamp\":1703781638647501000,\"task_end_timestamp\":1703781641829349000,\"compile_start_timestamp\":1703781638620016000,\"compile_end_timestamp\":1703781638647441000,\"read_wait_index_start_timestamp\":1703781638622464000,\"read_wait_index_end_timestamp\":1703781638634583000,\"local_input_bytes\":23479826799,\"remote_input_bytes\":0,\"output_bytes\":0,\"status\":\"FINISHED\",\"error_message\":\"\",\"cpu_ru\":28697.666666666668,\"read_ru\":655855.8811035156,\"memory_peak\":2061153151}"] [source="mpp_task_tracing MPP<gather_id:1, query_ts:1703781638601123926, local_query_id:503, server_id:374, start_ts:446636133861556226,task_id:1>"] [thread_id=594]
	   {
		"id": "TableFullScan_35",
		"type": "TableScan",
		"children": [],
		"outbound_rows": 321641463,
		"outbound_blocks": 11994,
		"outbound_bytes": 23479826799,
		"outbound_allocated_bytes": 32900678464,
		"concurrency": 72,
		"execution_time_ns": 2156998119,
		"connection_details": [{
			"is_local": true,
			"packets": 0,
			"bytes": 23479826799
		}, {
			"is_local": false,
			"packets": 0,
			"bytes": 0
		}],
		"scan_details": {
			"build_bitmap_time": "107084.878ms",
			"create_snapshot_time": "3.113ms",
			"delta_bytes": 638315925,
			"delta_rows": 6719115,
			"disagg_cache_hit_size": 0,
			"disagg_cache_miss_size": 0,
			"dmfile_read_time": "63607.359ms",
			"dmfile_scan_rows": 1916326703,
			"dmfile_skip_rows": 78937719,
			"late_materialization_skip_rows": 12677929,
			"learner_read_time": "12.917ms",
			"local_region_num": 0,
			"mvcc_input_bytes": 7888726886,
			"mvcc_input_rows": 464042758,
			"mvcc_skip_rows": 6653709,
			"num_columns": 9,
			"num_read_tasks": 587,
			"num_segments": 587,
			"read_bytes": 42982171024,
			"read_mode": "Bitmap",
			"remote_region_num": 0
		}
	}],

-- no late materialization
set tidb_opt_enable_late_materialization=0;
explain analyze select   ol_number,          sum(ol_quantity) as sum_qty,          sum(ol_amount) as sum_amount,          avg(ol_quantity) as avg_qty,          avg(ol_amount) as avg_amount,          min(ol_delivery_d) as min_deliver_d,          max(ol_delivery_d) as min_deliver_d,          sum(length(ol_dist_info)),          sum(ol_i_id),max(ol_o_id),max(ol_d_id),max(ol_w_id),sum(ol_number),          count(*) as count_order from     order_line where    ol_delivery_d > '2007-01-02 00:00:00.000000' group by ol_number order by ol_number;

+----------------------------------------+--------------+-----------+--------------+------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| id                                     | estRows      | actRows   | task         | access object    | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                   | operator info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        | memory    | disk    |
+----------------------------------------+--------------+-----------+--------------+------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| Sort_6                                 | 10.67        | 15        | root         |                  | time:3.07s, loops:2, RU:0.000000                                                                                                                                                                                                                                                                                                                                                                                                                 | chbenchmark.order_line.ol_number                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | 12.5 KB   | 0 Bytes |
| └─TableReader_54                       | 10.67        | 15        | root         |                  | time:3.07s, loops:2, cop_task: {num: 14, max: 0s, min: 0s, avg: 0s, p95: 0s, copr_cache_hit_ratio: 0.00}                                                                                                                                                                                                                                                                                                                                         | MppVersion: 2, data:ExchangeSender_53                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | 923 Bytes | N/A     |
|   └─ExchangeSender_53                  | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.07s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                  | ExchangeType: PassThrough                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            | N/A       | N/A     |
|     └─Projection_9                     | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.07s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                  | chbenchmark.order_line.ol_number, Column#12, Column#13, Column#14, Column#15, Column#16, Column#17, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24                                                                                                                                                                                                                                                                                                                                      | N/A       | N/A     |
|       └─Projection_49                  | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.07s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                  | Column#12, Column#13, div(Column#14, cast(case(eq(Column#79, 0), 1, Column#79), decimal(20,0) BINARY))->Column#14, div(Column#15, cast(case(eq(Column#80, 0), 1, Column#80), decimal(20,0) BINARY))->Column#15, Column#16, Column#17, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24, chbenchmark.order_line.ol_number                                                                                                                                                                  | N/A       | N/A     |
|         └─HashAgg_50                   | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.07s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                  | group by:chbenchmark.order_line.ol_number, funcs:sum(Column#81)->Column#12, funcs:sum(Column#82)->Column#13, funcs:sum(Column#83)->Column#79, funcs:sum(Column#84)->Column#14, funcs:sum(Column#85)->Column#80, funcs:sum(Column#86)->Column#15, funcs:min(Column#87)->Column#16, funcs:max(Column#88)->Column#17, funcs:sum(Column#89)->Column#18, funcs:sum(Column#90)->Column#19, funcs:max(Column#91)->Column#20, funcs:max(Column#92)->Column#21, funcs:max(Column#93)->Column#22, funcs:sum(Column#94)->Col... | N/A       | N/A     |
|           └─ExchangeReceiver_52        | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.07s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                  | stream_count: 36                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | N/A       | N/A     |
|             └─ExchangeSender_51        | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.07s, loops:1, threads:1}                                                                                                                                                                                                                                                                                                                                                                                                    | ExchangeType: HashPartition, Compression: FAST, Hash Cols: [name: chbenchmark.order_line.ol_number, collate: binary], stream_count: 36                                                                                                                                                                                                                                                                                                                                                                               | N/A       | N/A     |
|               └─HashAgg_47             | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.06s, loops:1, threads:1}                                                                                                                                                                                                                                                                                                                                                                                                    | group by:Column#111, funcs:sum(Column#97)->Column#81, funcs:sum(Column#98)->Column#82, funcs:count(Column#99)->Column#83, funcs:sum(Column#100)->Column#84, funcs:count(Column#101)->Column#85, funcs:sum(Column#102)->Column#86, funcs:min(Column#103)->Column#87, funcs:max(Column#104)->Column#88, funcs:sum(Column#105)->Column#89, funcs:sum(Column#106)->Column#90, funcs:max(Column#107)->Column#91, funcs:max(Column#108)->Column#92, funcs:max(Column#109)->Column#93, funcs:sum(Column#110)->Column#94,... | N/A       | N/A     |
|                 └─Projection_57        | 320161490.84 | 321641463 | mpp[tiflash] |                  | tiflash_task:{time:2.36s, loops:11994, threads:72}                                                                                                                                                                                                                                                                                                                                                                                               | cast(chbenchmark.order_line.ol_quantity, decimal(10,0) BINARY)->Column#97, chbenchmark.order_line.ol_amount->Column#98, chbenchmark.order_line.ol_quantity->Column#99, cast(chbenchmark.order_line.ol_quantity, decimal(10,0) BINARY)->Column#100, chbenchmark.order_line.ol_amount->Column#101, chbenchmark.order_line.ol_amount->Column#102, chbenchmark.order_line.ol_delivery_d->Column#103, chbenchmark.order_line.ol_delivery_d->Column#104, cast(length(chbenchmark.order_line.ol_dist_info), decimal(20,0... | N/A       | N/A     |
|                   └─Selection_36       | 320161490.84 | 321641463 | mpp[tiflash] |                  | tiflash_task:{time:1.78s, loops:11994, threads:72}                                                                                                                                                                                                                                                                                                                                                                                               | gt(chbenchmark.order_line.ol_delivery_d, 2007-01-02 00:00:00.000000)                                                                                                                                                                                                                                                                                                                                                                                                                                                 | N/A       | N/A     |
|                     └─TableFullScan_35 | 457389049.00 | 457389049 | mpp[tiflash] | table:order_line | tiflash_task:{time:1.39s, loops:12141, threads:72}, tiflash_scan:{dtfile:{total_scanned_packs:112250, total_skipped_packs:0, total_scanned_rows:914676276, total_skipped_rows:0, total_rs_index_check_time: 323ms, total_read_time: 61540ms, total_disagg_read_cache_hit_size: 0, total_disagg_read_cache_miss_size: 0}, total_create_snapshot_time: 2ms, total_local_region_num: 589, total_remote_region_num: 0, total_learner_read_time: 8ms} | keep order:false                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | N/A       | N/A     |
+----------------------------------------+--------------+-----------+--------------+------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
7362:[2023/12/29 00:42:11.133 +08:00] [INFO] [MPPTaskStatistics.cpp:138] ["{\"query_tso\":446636157310599171,\"task_id\":1,\"is_root\":false,\"sender_executor_id\":\"ExchangeSender_51\",\"executors\":[{\"id\":\"ExchangeSender_51\",\"type\":\"ExchangeSender\",\"children\":[\"HashAgg_47\"],\"outbound_rows\":15,\"outbound_blocks\":1,\"outbound_bytes\":2700,\"outbound_allocated_bytes\":6054,\"concurrency\":1,\"execution_time_ns\":3048001958,\"partition_num\":1,\"sender_target_task_ids\":[2],\"exchange_type\":\"Hash\",\"connection_details\":[{\"tunnel_id\":\"tunnel1+2\",\"sender_target_task_id\":2,\"sender_target_host\":\"10.2.12.81:9520\",\"is_local\":true,\"packets\":1,\"bytes\":26377}]},{\"id\":\"HashAgg_47\",\"type\":\"Agg\",\"children\":[\"Projection_57\"],\"outbound_rows\":15,\"outbound_blocks\":1,\"outbound_bytes\":2625,\"outbound_allocated_bytes\":5824,\"concurrency\":1,\"execution_time_ns\":3044001956},{\"id\":\"Projection_57\",\"type\":\"Projection\",\"children\":[\"Selection_36\"],\"outbound_rows\":321641463,\"outbound_blocks\":11994,\"outbound_bytes\":24766392651,\"outbound_allocated_bytes\":28815589970,\"concurrency\":72,\"execution_time_ns\":2342001509},{\"id\":\"Selection_36\",\"type\":\"Selection\",\"children\":[\"TableFullScan_35\"],\"outbound_rows\":321641463,\"outbound_blocks\":11994,\"outbound_bytes\":23479826799,\"outbound_allocated_bytes\":32900678464,\"concurrency\":72,\"execution_time_ns\":1759001131},{\"id\":\"TableFullScan_35\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":457389049,\"outbound_blocks\":12141,\"outbound_bytes\":33389400577,\"outbound_allocated_bytes\":42645066688,\"concurrency\":72,\"execution_time_ns\":1370000883,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":33389400577},{\"is_local\":false,\"packets\":0,\"bytes\":0}],\"scan_details\":{\"build_bitmap_time\":\"67339.978ms\",\"create_snapshot_time\":\"2.140ms\",\"create_stream_time\":\"96911.415ms\",\"delta_bytes\":638315925,\"delta_rows\":6719115,\"disagg_cache_hit_size\":0,\"disagg_cache_miss_size\":0,\"dmfile_read_time\":\"61540.283ms\",\"dmfile_scan_rows\":914676276,\"dmfile_skip_rows\":0,\"late_materialization_skip_rows\":0,\"learner_read_time\":\"8.935ms\",\"local_region_num\":0,\"mvcc_input_bytes\":7888726886,\"mvcc_input_rows\":464042758,\"mvcc_skip_rows\":6653709,\"num_columns\":9,\"num_read_tasks\":587,\"num_segments\":587,\"read_bytes\":41274410960,\"read_mode\":\"Bitmap\",\"remote_region_num\":0}}],\"host\":\"10.2.12.81:9520\",\"task_init_timestamp\":1703781728070933000,\"task_start_timestamp\":1703781728089125000,\"task_end_timestamp\":1703781731133684000,\"compile_start_timestamp\":1703781728072014000,\"compile_end_timestamp\":1703781728089094000,\"read_wait_index_start_timestamp\":1703781728073876000,\"read_wait_index_end_timestamp\":1703781728082239000,\"local_input_bytes\":33389400577,\"remote_input_bytes\":0,\"output_bytes\":0,\"status\":\"FINISHED\",\"error_message\":\"\",\"cpu_ru\":44555,\"read_ru\":629797.5305175781,\"memory_peak\":2517584929}"] [source="mpp_task_tracing MPP<gather_id:1, query_ts:1703781728067568358, local_query_id:504, server_id:374, start_ts:446636157310599171,task_id:1>"] [thread_id=602]
        {
		"id": "TableFullScan_35",
		"type": "TableScan",
		"children": [],
		"outbound_rows": 457389049,
		"outbound_blocks": 12141,
		"outbound_bytes": 33389400577,
		"outbound_allocated_bytes": 42645066688,
		"concurrency": 72,
		"execution_time_ns": 1370000883,
		"connection_details": [{
			"is_local": true,
			"packets": 0,
			"bytes": 33389400577
		}, {
			"is_local": false,
			"packets": 0,
			"bytes": 0
		}],
		"scan_details": {
			"build_bitmap_time": "67339.978ms",
			"create_snapshot_time": "2.140ms",
			"delta_bytes": 638315925,
			"delta_rows": 6719115,
			"disagg_cache_hit_size": 0,
			"disagg_cache_miss_size": 0,
			"dmfile_read_time": "61540.283ms",
			"dmfile_scan_rows": 914676276,
			"dmfile_skip_rows": 0,
			"late_materialization_skip_rows": 0,
			"learner_read_time": "8.935ms",
			"local_region_num": 0,
			"mvcc_input_bytes": 7888726886,
			"mvcc_input_rows": 464042758,
			"mvcc_skip_rows": 6653709,
			"num_columns": 9,
			"num_read_tasks": 587,
			"num_segments": 587,
			"read_bytes": 41274410960,
			"read_mode": "Bitmap",
			"remote_region_num": 0
		}
	}],

-- no bitmap and late materialization
set tidb_opt_enable_late_materialization=0;
explain analyze select   ol_number,          sum(ol_quantity) as sum_qty,          sum(ol_amount) as sum_amount,          avg(ol_quantity) as avg_qty,          avg(ol_amount) as avg_amount,          min(ol_delivery_d) as min_deliver_d,          max(ol_delivery_d) as min_deliver_d,          sum(length(ol_dist_info)),          sum                               -> (ol_i_id),max(ol_o_id),max(ol_d_id),max(ol_w_id),sum(ol_number),          count(*) as count_order from     order_line where    ol_delivery_d > '2007-01-02 00:00:00.000000' group by ol_number order by ol_number;
+----------------------------------------+--------------+-----------+--------------+------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| id                                     | estRows      | actRows   | task         | access object    | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                 | operator info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        | memory    | disk    |
+----------------------------------------+--------------+-----------+--------------+------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| Sort_6                                 | 10.67        | 15        | root         |                  | time:3.38s, loops:2, RU:0.000000                                                                                                                                                                                                                                                                                                                                                                                                               | chbenchmark.order_line.ol_number                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | 12.5 KB   | 0 Bytes |
| └─TableReader_54                       | 10.67        | 15        | root         |                  | time:3.38s, loops:2, cop_task: {num: 14, max: 0s, min: 0s, avg: 0s, p95: 0s, copr_cache_hit_ratio: 0.00}                                                                                                                                                                                                                                                                                                                                       | MppVersion: 2, data:ExchangeSender_53                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | 923 Bytes | N/A     |
|   └─ExchangeSender_53                  | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                | ExchangeType: PassThrough                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            | N/A       | N/A     |
|     └─Projection_9                     | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                | chbenchmark.order_line.ol_number, Column#12, Column#13, Column#14, Column#15, Column#16, Column#17, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24                                                                                                                                                                                                                                                                                                                                      | N/A       | N/A     |
|       └─Projection_49                  | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                | Column#12, Column#13, div(Column#14, cast(case(eq(Column#79, 0), 1, Column#79), decimal(20,0) BINARY))->Column#14, div(Column#15, cast(case(eq(Column#80, 0), 1, Column#80), decimal(20,0) BINARY))->Column#15, Column#16, Column#17, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24, chbenchmark.order_line.ol_number                                                                                                                                                                  | N/A       | N/A     |
|         └─HashAgg_50                   | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                | group by:chbenchmark.order_line.ol_number, funcs:sum(Column#81)->Column#12, funcs:sum(Column#82)->Column#13, funcs:sum(Column#83)->Column#79, funcs:sum(Column#84)->Column#14, funcs:sum(Column#85)->Column#80, funcs:sum(Column#86)->Column#15, funcs:min(Column#87)->Column#16, funcs:max(Column#88)->Column#17, funcs:sum(Column#89)->Column#18, funcs:sum(Column#90)->Column#19, funcs:max(Column#91)->Column#20, funcs:max(Column#92)->Column#21, funcs:max(Column#93)->Column#22, funcs:sum(Column#94)->Col... | N/A       | N/A     |
|           └─ExchangeReceiver_52        | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:13, threads:36}                                                                                                                                                                                                                                                                                                                                                                                                | stream_count: 36                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | N/A       | N/A     |
|             └─ExchangeSender_51        | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:1, threads:1}                                                                                                                                                                                                                                                                                                                                                                                                  | ExchangeType: HashPartition, Compression: FAST, Hash Cols: [name: chbenchmark.order_line.ol_number, collate: binary], stream_count: 36                                                                                                                                                                                                                                                                                                                                                                               | N/A       | N/A     |
|               └─HashAgg_47             | 10.67        | 15        | mpp[tiflash] |                  | tiflash_task:{time:3.38s, loops:1, threads:1}                                                                                                                                                                                                                                                                                                                                                                                                  | group by:Column#111, funcs:sum(Column#97)->Column#81, funcs:sum(Column#98)->Column#82, funcs:count(Column#99)->Column#83, funcs:sum(Column#100)->Column#84, funcs:count(Column#101)->Column#85, funcs:sum(Column#102)->Column#86, funcs:min(Column#103)->Column#87, funcs:max(Column#104)->Column#88, funcs:sum(Column#105)->Column#89, funcs:sum(Column#106)->Column#90, funcs:max(Column#107)->Column#91, funcs:max(Column#108)->Column#92, funcs:max(Column#109)->Column#93, funcs:sum(Column#110)->Column#94,... | N/A       | N/A     |
|                 └─Projection_57        | 320161490.84 | 321641463 | mpp[tiflash] |                  | tiflash_task:{time:2.48s, loops:7247, threads:72}                                                                                                                                                                                                                                                                                                                                                                                              | cast(chbenchmark.order_line.ol_quantity, decimal(10,0) BINARY)->Column#97, chbenchmark.order_line.ol_amount->Column#98, chbenchmark.order_line.ol_quantity->Column#99, cast(chbenchmark.order_line.ol_quantity, decimal(10,0) BINARY)->Column#100, chbenchmark.order_line.ol_amount->Column#101, chbenchmark.order_line.ol_amount->Column#102, chbenchmark.order_line.ol_delivery_d->Column#103, chbenchmark.order_line.ol_delivery_d->Column#104, cast(length(chbenchmark.order_line.ol_dist_info), decimal(20,0... | N/A       | N/A     |
|                   └─Selection_36       | 320161490.84 | 321641463 | mpp[tiflash] |                  | tiflash_task:{time:1.78s, loops:7247, threads:72}                                                                                                                                                                                                                                                                                                                                                                                              | gt(chbenchmark.order_line.ol_delivery_d, 2007-01-02 00:00:00.000000)                                                                                                                                                                                                                                                                                                                                                                                                                                                 | N/A       | N/A     |
|                     └─TableFullScan_35 | 457389049.00 | 457389049 | mpp[tiflash] | table:order_line | tiflash_task:{time:1.27s, loops:7381, threads:72}, tiflash_scan:{dtfile:{total_scanned_packs:56125, total_skipped_packs:0, total_scanned_rows:457338138, total_skipped_rows:0, total_rs_index_check_time: 35ms, total_read_time: 74543ms, total_disagg_read_cache_hit_size: 0, total_disagg_read_cache_miss_size: 0}, total_create_snapshot_time: 3ms, total_local_region_num: 589, total_remote_region_num: 0, total_learner_read_time: 17ms} | keep order:false                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     | N/A       | N/A     |
+----------------------------------------+--------------+-----------+--------------+------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
5016:[2023/12/29 01:13:46.861 +08:00] [INFO] [MPPTaskStatistics.cpp:138] ["{\"query_tso\":446636654191181826,\"task_id\":1,\"is_root\":false,\"sender_executor_id\":\"ExchangeSender_51\",\"executors\":[{\"id\":\"ExchangeSender_51\",\"type\":\"ExchangeSender\",\"children\":[\"HashAgg_47\"],\"outbound_rows\":15,\"outbound_blocks\":1,\"outbound_bytes\":2700,\"outbound_allocated_bytes\":6054,\"concurrency\":1,\"execution_time_ns\":3351993264,\"partition_num\":1,\"sender_target_task_ids\":[2],\"exchange_type\":\"Hash\",\"connection_details\":[{\"tunnel_id\":\"tunnel1+2\",\"sender_target_task_id\":2,\"sender_target_host\":\"10.2.12.81:9520\",\"is_local\":true,\"packets\":1,\"bytes\":26377}]},{\"id\":\"HashAgg_47\",\"type\":\"Agg\",\"children\":[\"Projection_57\"],\"outbound_rows\":15,\"outbound_blocks\":1,\"outbound_bytes\":2625,\"outbound_allocated_bytes\":5824,\"concurrency\":1,\"execution_time_ns\":3347993272},{\"id\":\"Projection_57\",\"type\":\"Projection\",\"children\":[\"Selection_36\"],\"outbound_rows\":321641463,\"outbound_blocks\":7247,\"outbound_bytes\":24766392651,\"outbound_allocated_bytes\":29046976104,\"concurrency\":72,\"execution_time_ns\":2456995062},{\"id\":\"Selection_36\",\"type\":\"Selection\",\"children\":[\"TableFullScan_35\"],\"outbound_rows\":321641463,\"outbound_blocks\":7247,\"outbound_bytes\":23479826799,\"outbound_allocated_bytes\":34766573184,\"concurrency\":72,\"execution_time_ns\":1756996468},{\"id\":\"TableFullScan_35\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":457389049,\"outbound_blocks\":7381,\"outbound_bytes\":33389400577,\"outbound_allocated_bytes\":53921185792,\"concurrency\":72,\"execution_time_ns\":1239997509,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":33389400577},{\"is_local\":false,\"packets\":0,\"bytes\":0}],\"scan_details\":{\"build_bitmap_time\":\"0.000ms\",\"create_snapshot_time\":\"3.129ms\",\"create_stream_time\":\"11363.734ms\",\"delta_bytes\":638315925,\"delta_rows\":6719115,\"disagg_cache_hit_size\":0,\"disagg_cache_miss_size\":0,\"dmfile_read_time\":\"74543.014ms\",\"dmfile_scan_rows\":457338138,\"dmfile_skip_rows\":0,\"late_materialization_skip_rows\":0,\"learner_read_time\":\"17.675ms\",\"local_region_num\":0,\"mvcc_input_bytes\":41763848220,\"mvcc_input_rows\":464042758,\"mvcc_skip_rows\":6653709,\"num_columns\":9,\"num_read_tasks\":587,\"num_segments\":587,\"read_bytes\":41763848220,\"read_mode\":\"Normal\",\"remote_region_num\":0}}],\"host\":\"10.2.12.81:9520\",\"task_init_timestamp\":1703783623484337000,\"task_start_timestamp\":1703783623513080000,\"task_end_timestamp\":1703783626861578000,\"compile_start_timestamp\":1703783623485328000,\"compile_end_timestamp\":1703783623513046000,\"read_wait_index_start_timestamp\":1703783623487125000,\"read_wait_index_end_timestamp\":1703783623504283000,\"local_input_bytes\":33389400577,\"remote_input_bytes\":0,\"output_bytes\":0,\"status\":\"FINISHED\",\"error_message\":\"\",\"cpu_ru\":54400.666666666664,\"read_ru\":637265.7504272461,\"memory_peak\":6078342192}"] [source="mpp_task_tracing MPP<gather_id:1, query_ts:1703783623480873181, local_query_id:508, server_id:374, start_ts:446636654191181826,task_id:1>"] [thread_id=619]
	  {
		"id": "TableFullScan_35",
		"type": "TableScan",
		"children": [],
		"outbound_rows": 457389049,
		"outbound_blocks": 7381,
		"outbound_bytes": 33389400577,
		"outbound_allocated_bytes": 53921185792,
		"concurrency": 72,
		"execution_time_ns": 1239997509,
		"connection_details": [{
			"is_local": true,
			"packets": 0,
			"bytes": 33389400577
		}, {
			"is_local": false,
			"packets": 0,
			"bytes": 0
		}],
		"scan_details": {
			"build_bitmap_time": "0.000ms",
			"create_snapshot_time": "3.129ms",
			"delta_bytes": 638315925,
			"delta_rows": 6719115,
			"disagg_cache_hit_size": 0,
			"disagg_cache_miss_size": 0,
			"dmfile_read_time": "74543.014ms",
			"dmfile_scan_rows": 457338138,
			"dmfile_skip_rows": 0,
			"late_materialization_skip_rows": 0,
			"learner_read_time": "17.675ms",
			"local_region_num": 0,
			"mvcc_input_bytes": 41763848220,
			"mvcc_input_rows": 464042758,
			"mvcc_skip_rows": 6653709,
			"num_columns": 9,
			"num_read_tasks": 587,
			"num_segments": 587,
			"read_bytes": 41763848220,
			"read_mode": "Normal",
			"remote_region_num": 0
		}
	}]
  • Unit test
  • Integration test
  • Manual test (add detailed scripts or steps below)
  • No code

Side effects

  • Performance regression: Consumes more CPU
  • Performance regression: Consumes more Memory
  • Breaking backward compatibility

Documentation

  • Affects user behaviors
  • Contains syntax changes
  • Contains variable changes
  • Contains experimental features
  • Changes MySQL compatibility

Release note

Change the default log level to "INFO"

@ti-chi-bot ti-chi-bot added release-note Denotes a PR that will be considered when it comes time to generate release notes. size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. type/cherry-pick-for-release-7.1 This PR is cherry-picked to release-7.1 from a source PR. labels Dec 29, 2023
@ti-chi-bot ti-chi-bot mentioned this pull request Dec 29, 2023
Merged
12 tasks
@ti-chi-bot ti-chi-bot bot added do-not-merge/cherry-pick-not-approved size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. and removed size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. labels Dec 29, 2023
@ti-chi-bot ti-chi-bot bot added size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. and removed size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. labels Dec 29, 2023
@ti-chi-bot ti-chi-bot bot added size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. and removed size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. labels Dec 30, 2023
@JaySon-Huang
Copy link
Contributor

/run-all-tests

@JaySon-Huang
Copy link
Contributor

/run-all-tests

@ti-chi-bot ti-chi-bot added the cherry-pick-approved Cherry pick PR approved by release team. label Jan 3, 2024
@JaySon-Huang
Copy link
Contributor

/run-all-tests

@ti-chi-bot ti-chi-bot bot added needs-1-more-lgtm Indicates a PR needs 1 more LGTM. approved labels Jan 5, 2024
@JaySon-Huang
Copy link
Contributor

This PR also pick part of the following changes to release-7.1

/cc @JinheLin

@ti-chi-bot ti-chi-bot
Copy link
Contributor

ti-chi-bot bot commented Jan 5, 2024

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: JaySon-Huang, Lloyd-Pottiger

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:
  • OWNERS [JaySon-Huang,Lloyd-Pottiger]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@ti-chi-bot ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Jan 5, 2024
@ti-chi-bot ti-chi-bot
Copy link
Contributor

ti-chi-bot bot commented Jan 5, 2024

[LGTM Timeline notifier]

Timeline:

  • 2024-01-05 07:43:36.835300649 +0000 UTC m=+2415707.872527576: ☑️ agreed by JaySon-Huang.
  • 2024-01-05 07:49:17.612638192 +0000 UTC m=+2416048.649865120: ☑️ agreed by Lloyd-Pottiger.

@JaySon-Huang
Copy link
Contributor

/run-all-tests

@JaySon-Huang
Copy link
Contributor

/run-integration-test

@ti-chi-bot ti-chi-bot bot merged commit 704fae6 into pingcap:release-7.1 Jan 6, 2024
5 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@JaySon-Huang JaySon-Huang JaySon-Huang approved these changes

@Lloyd-Pottiger Lloyd-Pottiger Lloyd-Pottiger approved these changes

@JinheLin JinheLin Awaiting requested review from JinheLin

Assignees

@JaySon-Huang JaySon-Huang

Labels
approved cherry-pick-approved Cherry pick PR approved by release team. lgtm release-note Denotes a PR that will be considered when it comes time to generate release notes. size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. type/cherry-pick-for-release-7.1 This PR is cherry-picked to release-7.1 from a source PR.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
4 participants
@ti-chi-bot @JaySon-Huang @Lloyd-Pottiger @CalvinNeo