Purpose
If the time consumed for the compilation and execution of a query exceeds the threshold (specified for trace_log_slow_query_watermark), the query is considered a slow query, and the trace_log of the slow query is forcibly printed to the log. The trace_log file records the execution time of each phase in detail, which helps you analyze the cause of a slow query.
Identify a slow query
[2021-10-19 16:47:18.947121] TRACE [TRACE]obmp_base.cpp:134
[105909][0][YA92464589051-0005CEB0A443493C-0-0] [lt=8] [dc=0]
[slow query](TRACE=begin_ts=1634633228637094 2021-10-19 08:47:08.637094|
[process_begin] u=0 in_queue_time:16, receive_ts:1634633228939375, enqueue_ts:1634633228939377|
[start_sql] u=1 addr:{ip:"xx.xx.xx.xx", port:41995}|
[query_begin] u=1 trace_id:YA92464589051-0005CEB0A443493C-0-0|
[before_processor_run] u=5 |
[session] u=4 sid:3221502589, tenant_id:1|
[parse_begin] u=24 stmt:"select * from t where sleep(10)", stmt_len:31|
[cache_get_plan_begin] u=1 |
[cache_get_plan_end] u=25 |
[transform_with_outline_begin] u=2 |
[pc_fast_parse_start] u=67 |
[pc_fast_parse_end] u=5 |
[transform_with_outline_end] u=8 |
[resolve_begin] u=29 |
[analyze_precalc_expr_begin] u=210 |
[analyze_precalc_expr_end] u=9 |
[resolve_end] u=24 |
[transform_begin] u=106 |
[transform_end] u=319 |
[optimize_begin] u=4 |
[tl_calc_by_range_end] u=163 |
[tl_calc_part_id_end] u=0 |
[get_location_cache_begin] u=1 |
[renew_loc_by_sql_begin] u=16 |
[parse_begin] u=353 stmt:"SELECT * FROM __all_tenant_meta_table WHERE tenant_id = 1 AND table_id = 1099511677777 AND partition_id = 0 ORDER BY tenant_id, table_id, partition_id, svr_ip, svr_port", stmt_len:168|
[cache_get_plan_begin] u=2 |
[cache_get_plan_end] u=23 |
[transform_with_outline_begin] u=0 |
[pc_fast_parse_start] u=69 |
[pc_fast_parse_end] u=6 |
[transform_with_outline_end] u=6 |
[resolve_begin] u=28 |
[analyze_precalc_expr_begin] u=251 |
[analyze_precalc_expr_end] u=9 |
[resolve_end] u=18 |
[transform_begin] u=60 |
[transform_end] u=438 |
[optimize_begin] u=2 |
[tl_calc_by_range_end] u=136 |
[tl_calc_part_id_end] u=1 |
[get_location_cache_begin] u=0 |
[get_location_cache_end] u=19 |
[storage_estimation_begin] u=258 |
[storage_estimation_end] u=66 |
[optimize_end] u=212 |
[cg_begin] u=1 |
[cg_end] u=139 |
[plan_id] u=167 plan_id:7441|
[start_trans] u=15 trans_id:{hash:11136244619746343644, inc:85875, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228942267}|
[start_trans] u=0 trans_id:{hash:11136244619746343644, inc:85875, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228942267}, timeout:1634633238939375, start_time:1634633228940765|
[do_open_plan_begin] u=1 plan_id:7441|
[sql_start_stmt_begin] u=0 |
[sql_start_stmt_end] u=4 |
[exec_plan_begin] u=1 |
[exec_plan_end] u=2 |
[sql_start_participant_begin] u=0 |
[sql_start_participant_end] u=0 |
[do_open_plan_end] u=0 |
[storage_table_scan_begin] u=10 |
[storage_table_scan_end] u=20 |
[get_row] u=13 |
[close_plan_begin] u=28 |
[revert_scan_iter] u=4 |
[get_trans_result] u=0 ret:0, trans_id:{hash:11136244619746343644, inc:85875, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228942267}|
[end_participant_begin] u=1 |
[get_trans_result] u=1 ret:0, trans_id:{hash:11136244619746343644, inc:85875, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228942267}|
[end_participant] u=0 ret:0|
[end_participant_end] u=0 |
[start_end_stmt] u=0 |
[end_stmt] u=1 |
[close_plan_end] u=0 |
[affected_rows] u=0 affected_rows:-1|
[store_found_rows] u=1 found_rows:0, return_rows:2|
[auto_end_plan_begin] u=0 |
[end_trans] u=3 ret:0|
[auto_end_plan_end] u=1 |
[result_set_close] u=0 ret:0, arg1:0, arg2:0, arg3:-4008, async:false|
[renew_loc_by_sql_end] u=394 ret:0, table_id:1099511677777, partition_id:0|
[get_location_cache_end] u=16 |
[parse_begin] u=548 stmt:"SELECT partition_id, object_type, row_cnt as row_count, avg_row_len as avg_row_size, macro_blk_cnt as macro_block_num, micro_blk_cnt as micro_block_num, last_analyzed FROM __all_table_stat_v2 WHERE TENANT_ID = 1 AND TABLE_ID=1099511677777", stmt_len:239|
[cache_get_plan_begin] u=1 |
[cache_get_plan_end] u=18 |
[transform_with_outline_begin] u=1 |
[pc_fast_parse_start] u=53 |
[pc_fast_parse_end] u=7 |
[transform_with_outline_end] u=5 |
[resolve_begin] u=40 |
[analyze_precalc_expr_begin] u=149 |
[analyze_precalc_expr_end] u=18 |
[resolve_end] u=18 |
[transform_begin] u=45 |
[transform_end] u=251 |
[optimize_begin] u=1 |
[tl_calc_by_range_end] u=151 |
[tl_calc_part_id_end] u=0 |
[get_location_cache_begin] u=0 |
[renew_loc_by_sql_begin] u=7 |
[parse_begin] u=644 stmt:"SELECT * FROM __all_root_table WHERE tenant_id = 1 AND table_id = 1099511628104 AND partition_id = 0 ORDER BY tenant_id, table_id, partition_id, svr_ip, svr_port", stmt_len:161|
[cache_get_plan_begin] u=2 |
[tl_calc_by_range_end] u=35 |
[tl_calc_part_id_end] u=0 |
[pc_choose_plan] u=4 |
[check_priv] u=1 |
[cache_get_plan_end] u=0 |
[plan_id] u=1 plan_id:3514|
[start_trans] u=14 trans_id:{hash:7268543862466884666, inc:85881, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228944356}|
[start_trans] u=0 trans_id:{hash:7268543862466884666, inc:85881, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228944356}, timeout:1634633238939373, start_time:1634633228945153|
[do_open_plan_begin] u=1 plan_id:3514|
[sql_start_stmt_begin] u=0 |
[sql_start_stmt_end] u=4 |
[exec_plan_begin] u=0 |
[exec_plan_end] u=2 |
[sql_start_participant_begin] u=0 |
[sql_start_participant_end] u=1 |
[do_open_plan_end] u=0 |
[storage_table_scan_begin] u=10 |
[storage_table_scan_end] u=24 |
[close_plan_begin] u=44 |
[revert_scan_iter] u=2 |
[get_trans_result] u=1 ret:0, trans_id:{hash:7268543862466884666, inc:85881, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228944356}|
[end_participant_begin] u=1 |
[get_trans_result] u=1 ret:0, trans_id:{hash:7268543862466884666, inc:85881, addr:{ip:"xx.xx.xx.xx", port:43300}, t:1634633228944356}|
[end_participant] u=0 ret:0|
[end_participant_end] u=0 |
[start_end_stmt] u=0 |
[end_stmt] u=1 |
[close_plan_end] u=0 |
[affected_rows] u=0 affected_rows:-1|
[store_found_rows] u=1 found_rows:0, return_rows:2|
[auto_end_plan_begin] u=0 |
[end_trans] u=2 ret:0|
[auto_end_plan_end] u=2 |
[result_set_close] u=0 ret:0, arg1:0, arg2:0, arg3:-4008, async:false|
[renew_loc_by_sql_end] u=146 ret:0, table_id:1099511628104, partition_id:0|
[get_location_cache_end] u=21 |
[optimize_end] u=254 |
[cg_begin] u=1 |
[cg_end] u=78 |
[plan_id] u=123 plan_id:7442|
[start_trans] u=6 |
[start_trans] u=0 |
[do_open_plan_begin] u=0 |
[sql_start_stmt_begin] u=1 |
[sql_start_stmt_end] u=4 |
[exec_plan_begin] u=0 |
[exec_plan_end] u=2 |
[sql_start_participant_begin] u=0 |
[sql_start_participant_end] u=20 |
[do_open_plan_end] u=1 |
[storage_table_scan_begin] u=8 |
[storage_table_scan_end] u=17 |
[close_plan_begin] u=27 |
[revert_scan_iter] u=3 |
[get_trans_result] u=0 |
[end_participant_begin] u=1 |
[get_trans_result] u=0 |
[end_participant] u=0 ret:0|
[end_participant_end] u=1 |
[start_end_stmt] u=0 |
[end_stmt] u=0 |
[close_plan_end] u=1 |
[affected_rows] u=0 |
[store_found_rows] u=0 |
[auto_end_plan_begin] u=0 |
[end_trans] u=3 |
[auto_end_plan_end] u=6 |
[result_set_close] u=0 |
[optimize_end] u=263 |
[cg_begin] u=1 |
[cg_end] u=64 |
[plan_id] u=120 |
[exec_begin] u=1 |
[start_trans] u=5 |
[start_trans] u=0 |
[do_open_plan_begin] u=0 |
[sql_start_stmt_begin] u=1 |
[sql_start_stmt_end] u=13 |
[exec_plan_begin] u=0 |
[exec_plan_end] u=2 |
[sql_start_participant_begin] u=0 |
[sql_start_participant_end] u=1 |
[do_open_plan_end] u=0 |
[close_plan_begin] u=9989583 |
[end_participant_begin] u=7 |
[get_trans_result] u=2 |
[end_participant] u=0 |
[end_participant_end] u=1 |
[start_end_stmt] u=0 |
[end_stmt] u=2 |
[process_end] u=236 |
total_timeu=9996941 DROPPED_EVENTS=8)
Field description:
| Execution phase of a slow query | Description |
|---|---|
| process_begin | Starts processing. |
| start_sql | Starts processing the SQL statement. |
| query_begin | Starts running the query. |
| before_processor_run | The phase before the processor runs. |
| session | Obtains the session. |
| parse_begin | Starts the parser. |
| cache_get_plan_begin | Starts to get a plan from the plan cache. |
| cache_get_plan_end | Stops getting the plan from the plan cache. |
| transform_with_outline_begin | Starts to rewrite the SQL statement based on the outline. |
| pc_fast_parse_start | Starts the fast parser. |
| pc_fast_parse_end | Stops the fast parser. |
| transform_with_outline_end | Stops outline conversion. |
| resolve_begin | Starts the resolver. |
| analyze_precalc_expr_begin | Starts expression precomputation. |
| analyze_precalc_expr_end | Stops expression precomputation. |
| resolve_end | Stops the resolver. |
| transform_begin | Starts to rewrite. |
| transform_end | Stops rewriting. |
| optimize_begin | Starts optimization. |
| tl_calc_by_range_end | Stops the calculation of the table location based on the range. |
| tl_calc_part_id_end | Stops the calculation of the partition ID based on the table location. |
| get_location_cache_begin | Starts to get the local cache. |
| renew_loc_by_sql_begin | Starts SQL execution for updating the local table location cache. |
| get_location_cache_end | Starts to get the local table location cache. |
| storage_estimation_begin | Starts storage estimation. |
| storage_estimation_end | Stops storage estimation. |
| optimize_end | Stops optimization. |
| cg_begin | Starts code generation. |
| cg_end | Stops code generation. |
| plan_id | The ID of the plan. |
| start_trans | Starts the transaction. |
| do_open_plan_begin | Starts to open the execution plan. |
| sql_start_stmt_begin | Starts to execute the SQL statement. |
| sql_start_stmt_end | Stops executing the SQL statement. |
| exec_plan_begin | Starts the execution plan. |
| exec_plan_end | Stops the execution plan. |
| sql_start_participant_begin | Starts to enable the replica at the SQL layer. |
| sql_start_participant_end | Stops enabling the replica at the SQL layer. |
| do_open_plan_end | Starts opening the execution plan. |
| storage_table_scan_begin | Starts storage table scan. |
| storage_table_scan_end | Stops storage table scan. |
| get_row | Gets rows. |
| close_plan_begin | Starts to close the plan. |
| revert_scan_iter | Resets the scan items. |
| get_trans_result | Gets the transaction result set. |
| end_participant_begin | Starts to end the participant. |
| end_participant | Ends the participant. |
| end_participant_end | Stops ending the participant. |
| start_end_stmt | Starts ending statement. |
| end_stmt | Ends the statement. |
| close_plan_end | Stops closing the plan. |
| affected_rows | The affected rows. |
| store_found_rows | Stores discovered rows. |
| auto_end_plan_begin | Starts automatically closing the plan. |
| end_trans | Stops conversion. |
| auto_end_plan_end | Stops automatically closing the plan. |
| result_set_close | Closes the result set. |
| renew_loc_by_sql_end | Stops the execution of the statement for updating the local table location cache. |
| pc_choose_plan | The plan cache selects a plan. |
| check_priv | Checks the privileges of the account. |
| exec_begin | Starts the execution. |
| process_end | Stops the process. |
If the u=xxx field in the trace log denotes an excessively long interval, contact OceanBase Technical Support for troubleshooting.