截取一段 OBServer 日志的输出 slow query 部分，内容如下。
[2022-07-08 11:26:20.535074] TRACE [TRACE]obmp_base.cpp:948 [59127][2532][YB420A0A34F5-0005E247B18CF116] [lt=16] [dc=0] [slow query](TRACE=begin_ts=1657250749896387 2022-07-08 03:25:49.896387|[process_begin] u=0 in_queue_time:11, receive_ts:1657250749896375, enqueue_ts:1657250749896376|[start_sql] u=0 addr:{ip:"10.xx.xx.239", port:38896}|[query_begin] u=1 trace_id:YB420A0A34F5-0005E247B18CF116|[before_processor_run] u=4 |[session] u=2 sid:3223166492, tenant_id:1013|[parse_begin] u=16 stmt:"select * from t1 where str1 = 'xxxxxxxxxx';", stmt_len:55|[cache_get_plan_begin] u=4 |[calc_partition_location_begin] u=64 |[tl_calc_by_range_end] u=10 |[tl_calc_part_id_end] u=0 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=182 |[calc_partition_location_end] u=1 |[pc_choose_plan] u=46 |[check_priv] u=25 |[cache_get_plan_end] u=0 |[plan_id] u=1 plan_id:9320739|[exec_begin] u=2 arg1:false, end_trans_cb:false|[post_packet] u=46 ret:0, pcode:1808, addr:{ip:"10.xx.xx.247", port:2882}|[do_open_plan_begin] u=557 plan_id:9320739|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=0 |[exec_plan_begin] u=1 |[exec_plan_end] u=14 |[sql_start_participant_begin] u=0 |[sql_start_participant_end] u=1 |[do_open_plan_end] u=1 |[post_packet] u=533 ret:0, pcode:1311, addr:{ip:"10.xx.xx.232", port:2882}|[post_packet] u=109 ret:0, pcode:1311, addr:{ip:"10.xx.xx.xxx", port:2882}|[post_packet] u=93 ret:0, pcode:1311, addr:{ip:"10.xx.xx.249", port:2882}|[post_packet] u=90 ret:0, pcode:1311, addr:{ip:"10.xx.xx.240", port:2882}|[post_packet] u=88 ret:0, pcode:1311, addr:{ip:"10.xx.xx.245", port:2882}|[post_packet] u=93 ret:0, pcode:1311, addr:{ip:"10.xx.xx.242", port:2882}|[post_packet] u=85 ret:0, pcode:1311, addr:{ip:"10.xx.xx.243", port:2882}|[post_packet] u=88 ret:0, pcode:1311, addr:{ip:"10.xx.xx.248", port:2882}|[post_packet] u=87 ret:0, pcode:1311, addr:{ip:"10.xx.xx.247", port:2882}|[sqc_finish] u=387 dfo_id:0, sqc_id:0|[sqc_finish] u=129 dfo_id:0, sqc_id:4|[sqc_finish] u=134 dfo_id:0, sqc_id:3|[sqc_finish] u=3 dfo_id:0, sqc_id:2|[sqc_finish] u=135 dfo_id:0, sqc_id:6|[sqc_finish] u=45 dfo_id:0, sqc_id:5|[sqc_finish] u=61 dfo_id:0, sqc_id:8|[sqc_finish] u=447 dfo_id:0, sqc_id:7|[sqc_finish] u=30634787 dfo_id:0, sqc_id:1|[close_plan_begin] u=8 |[end_participant_begin] u=100 |[end_participant_end] u=0 |[start_end_stmt] u=0 |[end_stmt] u=0 |[close_plan_end] u=0 |[affected_rows] u=1 affected_rows:0|[store_found_rows] u=0 found_rows:0, return_rows:1|[auto_end_plan_begin] u=1 |[auto_end_plan_end] u=2 |[result_set_close] u=0 ret:0, arg1:0, arg2:0, arg3:-4008, async:false|[exec_end] u=16 |[query_end] u=100 |[process_end] u=17 run_ts:1657250749896392|total_timeu=30638618)
有时事件 [process_end] 耗时很长，u 会达到很大的值，比如：
[process_end] u=1700000
出现这种情况具体是由于 event 过多被 drop 导致的计算不准确，符合预期。一般当出现此类情况时，会伴随着大量 DROPPED_EVENTS。比如：
[sqc_finish] u=100 |[process_end] u=1700000 run_ts:1657250749896392|total_timeu=30638618 DROPPED_EVENTS=281
在事件 sqc_finish 与 process_end 之间，有 281 个 event 被丢弃，当计算 process_end 的耗时的时候，是取 process_end 与 sqc_finish 两个事件的执行时间差。由于两个 event 之间差了 281 个 event，最终差值变大，导致 process_end 的执行耗时非常大。
适用版本
OceanBase 数据库 V2.x 和 V3.x 版本。
