From 4cdfee04892b6b61ee1d62cd2c0f8051892d5004 Mon Sep 17 00:00:00 2001 From: raywill Date: Tue, 8 Nov 2022 11:05:39 +0000 Subject: [PATCH] make sql_plan_monitor db_time semantics user friendly --- .../ob_virtual_sql_plan_monitor.cpp | 2 +- .../diagnosis/ob_sql_plan_monitor_node_list.h | 4 ++-- src/sql/engine/ob_operator.cpp | 13 ++++++++++++- src/sql/engine/ob_operator.h | 3 ++- src/sql/engine/px/exchange/ob_px_transmit_op.cpp | 16 ++++++++++++---- src/sql/engine/px/exchange/ob_px_transmit_op.h | 3 ++- src/sql/engine/px/ob_px_task_process.cpp | 2 +- 7 files changed, 32 insertions(+), 11 deletions(-) diff --git a/src/observer/virtual_table/ob_virtual_sql_plan_monitor.cpp b/src/observer/virtual_table/ob_virtual_sql_plan_monitor.cpp index c1877562a..ec4f92297 100644 --- a/src/observer/virtual_table/ob_virtual_sql_plan_monitor.cpp +++ b/src/observer/virtual_table/ob_virtual_sql_plan_monitor.cpp @@ -733,7 +733,7 @@ int ObVirtualSqlPlanMonitor::convert_node_to_row(ObMonitorNode &node, ObNewRow * } case DB_TIME: { // concept: https://yuque.antfin.com/xiaochu.yh/doc/lt4toe/ - cells[cell_idx].set_int(node.cpu_time_); + cells[cell_idx].set_int(node.db_time_); break; } case USER_IO_WAIT_TIME: { diff --git a/src/share/diagnosis/ob_sql_plan_monitor_node_list.h b/src/share/diagnosis/ob_sql_plan_monitor_node_list.h index 1a31fea98..29a85381c 100644 --- a/src/share/diagnosis/ob_sql_plan_monitor_node_list.h +++ b/src/share/diagnosis/ob_sql_plan_monitor_node_list.h @@ -66,7 +66,7 @@ public: close_time_(0), rescan_times_(0), output_row_count_(0), - cpu_time_(0), + db_time_(0), block_time_(0), memory_used_(0), disk_read_count_(0), @@ -129,7 +129,7 @@ public: int64_t close_time_; int64_t rescan_times_; int64_t output_row_count_; - uint64_t cpu_time_; // rdtsc cpu cycles spend on this op and its child + uint64_t db_time_; // rdtsc cpu cycles spend on this op, include cpu instructions & io uint64_t block_time_; // rdtsc cpu cycles wait for network, io etc int64_t memory_used_; int64_t disk_read_count_; diff --git a/src/sql/engine/ob_operator.cpp b/src/sql/engine/ob_operator.cpp index f78e8da88..137a1c122 100644 --- a/src/sql/engine/ob_operator.cpp +++ b/src/sql/engine/ob_operator.cpp @@ -478,6 +478,7 @@ ObOperator::ObOperator(ObExecContext &exec_ctx, const ObOpSpec &spec, ObOpInput need_init_before_get_row_(true), io_event_observer_(op_monitor_info_), cpu_begin_time_(0), + total_time_(0), batch_reach_end_(false), row_reach_end_(false), output_batches_b4_rescan_(0), @@ -643,7 +644,6 @@ int ObOperator::open() LOG_DEBUG("open op", K(ret), "op_type", op_name(), "op_id", spec_.id_, K(open_order)); } - return ret; } @@ -885,6 +885,15 @@ int ObOperator::submit_op_monitor_node() || (op_monitor_info_.close_time_ - ctx_.get_plan_start_time() > MONITOR_RUNNING_TIME_THRESHOLD)))) { + // exclude time cost in children, but px receive have no real children in exec view + uint64_t db_time = total_time_; // use temp var to avoid dis-order close + if (!spec_.is_receive()) { + for (int64_t i = 0; i < child_cnt_; i++) { + db_time -= children_[i]->total_time_; + } + } + // exclude io time cost + op_monitor_info_.db_time_ = db_time; IGNORE_RETURN list->submit_node(op_monitor_info_); LOG_DEBUG("debug monitor", K(spec_.id_)); } @@ -1174,6 +1183,7 @@ int ObOperator::filter_batch_rows(const ObExprPtrIArray &exprs, // copy ObPhyOperator::drain_exch int ObOperator::drain_exch() { + uint64_t cpu_begin_time = rdtsc(); int ret = OB_SUCCESS; /** * 1. try to open this operator @@ -1192,6 +1202,7 @@ int ObOperator::drain_exch() } } } + total_time_ += (rdtsc() - cpu_begin_time); return ret; } diff --git a/src/sql/engine/ob_operator.h b/src/sql/engine/ob_operator.h index 3310a055a..01f6f1df2 100644 --- a/src/sql/engine/ob_operator.h +++ b/src/sql/engine/ob_operator.h @@ -607,7 +607,7 @@ protected: } inline void end_cpu_time_counting() { - op_monitor_info_.cpu_time_ += (rdtsc() - cpu_begin_time_); + total_time_ += (rdtsc() - cpu_begin_time_); // move back to parent operator if (OB_LIKELY(spec_.get_parent())) { common::ObActiveSessionGuard::get_stat().plan_line_id_ = spec_.get_parent()->id_; @@ -617,6 +617,7 @@ protected: } uint64_t cpu_begin_time_; // start of counting cpu time + uint64_t total_time_; // total time cost on this op, including io & cpu time protected: bool batch_reach_end_; bool row_reach_end_; diff --git a/src/sql/engine/px/exchange/ob_px_transmit_op.cpp b/src/sql/engine/px/exchange/ob_px_transmit_op.cpp index 4995f701d..42d15f03e 100644 --- a/src/sql/engine/px/exchange/ob_px_transmit_op.cpp +++ b/src/sql/engine/px/exchange/ob_px_transmit_op.cpp @@ -209,6 +209,14 @@ int ObPxTransmitOp::inner_open() return ret; } +int ObPxTransmitOp::transmit() +{ + int64_t cpu_begin_time = rdtsc(); + int ret = do_transmit(); + total_time_ += (rdtsc() - cpu_begin_time_); + return ret; +} + int ObPxTransmitOp::fetch_first_row() { int ret = OB_SUCCESS; @@ -530,7 +538,7 @@ int ObPxTransmitOp::send_rows_one_by_one(ObSliceIdxCalc &slice_calc) } else if (OB_FAIL(send_eof_row())) { // overwrite err code LOG_WARN("fail send eof rows to channels", K(ret)); } - op_monitor_info_.cpu_time_ += (rdtsc() - begin_cpu_time); + op_monitor_info_.db_time_ += (rdtsc() - begin_cpu_time); break; } } @@ -556,7 +564,7 @@ int ObPxTransmitOp::send_rows_one_by_one(ObSliceIdxCalc &slice_calc) } } } - op_monitor_info_.cpu_time_ += (rdtsc() - begin_cpu_time); + op_monitor_info_.db_time_ += (rdtsc() - begin_cpu_time); } if (OB_ITER_END == ret) { ret = OB_SUCCESS; @@ -667,11 +675,11 @@ int ObPxTransmitOp::send_rows_in_batch(ObSliceIdxCalc &slice_calc) } else if (OB_FAIL(send_eof_row())) { LOG_WARN("fail send eof rows to channels", K(ret)); } - op_monitor_info_.cpu_time_ += (rdtsc() - begin_cpu_time); + op_monitor_info_.db_time_ += (rdtsc() - begin_cpu_time); break; } // for those break out ops - op_monitor_info_.cpu_time_ += (rdtsc() - begin_cpu_time); + op_monitor_info_.db_time_ += (rdtsc() - begin_cpu_time); } LOG_TRACE("Transmit time record", K(row_count), K(ret)); return ret; diff --git a/src/sql/engine/px/exchange/ob_px_transmit_op.h b/src/sql/engine/px/exchange/ob_px_transmit_op.h index ec9049d7f..293c07f9f 100644 --- a/src/sql/engine/px/exchange/ob_px_transmit_op.h +++ b/src/sql/engine/px/exchange/ob_px_transmit_op.h @@ -102,7 +102,7 @@ public: virtual int inner_close() override; virtual int inner_get_next_row() override; virtual int inner_get_next_batch(const int64_t max_row_cnt) override; - virtual int do_transmit() = 0; + virtual int transmit(); public: int init_channel(ObPxTransmitOpInput &trans_input); int init_dfc(dtl::ObDtlDfoKey &parent_key, dtl::ObDtlSqcInfo &child_info); @@ -111,6 +111,7 @@ public: common::ObIArray &get_task_channels() { return task_channels_; } void set_batch_param_remain(bool batch_param_remain) { batch_param_remain_ = batch_param_remain; } protected: + virtual int do_transmit() = 0; int init_channels_cur_block(common::ObIArray &dtl_chs); protected: int link_ch_sets(ObPxTaskChSet &ch_set, diff --git a/src/sql/engine/px/ob_px_task_process.cpp b/src/sql/engine/px/ob_px_task_process.cpp index f724ef1d0..b5c5914d9 100644 --- a/src/sql/engine/px/ob_px_task_process.cpp +++ b/src/sql/engine/px/ob_px_task_process.cpp @@ -288,7 +288,7 @@ int ObPxTaskProcess::execute(ObOpSpec &root_spec) static_cast(root)->set_batch_param_remain(false); } } - OZ(static_cast(root)->do_transmit()); + OZ(static_cast(root)->transmit()); } if (OB_FAIL(ret)) {