慢sql日志解读

grep “slow query” observer.log.20250714094057
[2025-07-14 09:38:56.223878] TRACE [TRACE]obmp_base.cpp:146 [10436][0][YB420A570182-00062E6DDF9EAFAE-0-0] [lt=10] [dc=0] [slow query](TRACE=begin_ts=1752457115902080 2025-07-14 01:38:35.902080
[start_sql] u=0 addr:{ip:“10...131”, port:27279}
[process_begin] u=0 addr:{ip:“10...131”, port:27279}, in_queue_time:15, receive_ts:1752457115902064, enqueue_ts:1752457115902065, trace_id:YB420A570182-00062E6DDF9EAFAE-0-0
[session] u=2 sid:3221617095, tenant_id:1038
[parse_begin] u=3 stmt:“select FILE_NAME, START_TIME, FAILURE_NUMBER, ERROR_CODE, STEP_DESC, STEP_TYPE, TRAN_DATE, RUN_DATE, END_TIME, TOTAL_NUMBER, APP_HEAD, JOB_RUN_ID, HOST_IP, SYS_HEAD, ATTR_JSON, SOURCE_TYPE, BATCH_NO, FILE_PATH, FILE_MD5, BRANCH_ID, FILE_TYPE, SUCCESS_NUMBER, ERROR_DESC, PROCESS_TYPE, USER_ID, OPERATION_ID, BATCH_CLASS, JOB_ID, CHANNEL_SEQ_NO, TRAN_STATUS from BATCH_ONLINE_CHECK where 1=1 and TRAN_DATE between timestamp ‘2025-07-14 00:00:00.0’ and timestamp ‘2025-07-15 00:00:00.0’ and branch_Id =”, stmt_len:509
[transform_with_outline_begin] u=16
[pc_fast_parse_start] u=140
[pc_fast_parse_end] u=16
[transform_with_outline_end] u=5
[resolve_begin] u=83
[resolve_end] u=468
[transform_begin] u=84
[transform_end] u=620
[optimize_begin] u=3
[get_location_cache_begin] u=260
[get_location_cache_end] u=10
[storage_estimation_begin] u=151
[storage_estimation_end] u=6399
[optimize_end] u=272
[cg_begin] u=0
[cg_end] u=160
[exec_begin] u=184 arg1:false, end_trans_cb:false, plan_id:226247
[do_open_plan_begin] u=5
[sql_start_stmt_begin] u=1
[sql_start_participant_begin] u=3
[storage_table_scan_begin] u=8
[storage_table_scan_end] u=579
[get_row] u=20311893
[result_set_close] u=137
[close_plan_begin] u=0
[revert_scan_iter] u=151
[end_participant_begin] u=4
[start_end_stmt] u=0
[affected_rows] u=0 affected_rows:0
[store_found_rows] u=1 found_rows:0, return_rows:1
[auto_end_plan_begin] u=0
[process_end] u=98 run_ts:1752457115902081
total_timeu=20321756)

大佬们,日志中get_row 耗时异常,请教一下,这个过程是做什么工作,为什么慢,看看怎么排查,怎么优化咧

table_rows:4141259, physical_range_rows:4098117, logical_range_rows:4044024, index_back_rows:0, output_rows:1694, est_method:local_storage, avaiable_index_name[BATCH_ONLINE_CHECK_IDX2,BATCH_ONLINE_CHECK_IDX3,BATCH_ONLINE_CHECK_IDX4,ONLINE_CHECK_BATCH_NO_TRAN_DATE_INX,BATCH_ONLINE_CHECK_IDX5,BATCH_ONLINE_CHECK], pruned_index_name[BATCH_ONLINE_CHECK_INDX,INDEX_FILENAME,BATCH_ONLINE_CHECK_IDX6], estimation info[table_id:1141293069684648, (table_type:1, version:0-1752429610451712-1752429610451712, logical_rc:4141259, physical_rc:4141259), (table_type:7, version:1752429600464367-1752429600464367-1752429641478324, logical_rc:62, physical_rc:255), (table_type:7, version:1752429641478324-1752446112021551-1752447886203796, logical_rc:-112340, physical_rc:-67462), (table_type:7, version:1752447886203796-1752451483015403-1752453274522775, logical_rc:8371, physical_rc:17386), (table_type:5, version:1752447886203796-1752451483015403-1752453274522775, logical_rc:0, physical_rc:0), (table_type:0, version:1752453274522775-1752453274522775-9223372036854775807, logical_rc:6672, physical_rc:6679)]

get row应该是获取observer计算出结果集的时间。如果想进行慢sql分析,建议使用obdiag的sql诊断分析帮忙获取一下该sql的相关信息。

SQL性能问题, 此处env中的trace_id对应gv$ob_sql_audit的trace_id

obdiag gather scene run --scene=observer.perf_sql --env “{db_connect=’-hxx -Pxx -uxx -pxx -Dxx’, trace_id=‘xx’}”

根据trace_id查询一下SQL_AUDIT,看下SQL的执行计划