make sql_plan_monitor db_time semantics user friendly

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: {

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_;

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;
 }
 

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_;

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;

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<dtl::ObDtlChannel *> &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::ObDtlChannel*> &dtl_chs);
 protected:
   int link_ch_sets(ObPxTaskChSet &ch_set,

src/sql/engine/px/ob_px_task_process.cpp

@@ -288,7 +288,7 @@ int ObPxTaskProcess::execute(ObOpSpec &root_spec)
           static_cast<ObPxTransmitOp *>(root)->set_batch_param_remain(false);
         }
       }
-      OZ(static_cast<ObPxTransmitOp *>(root)->do_transmit());
+      OZ(static_cast<ObPxTransmitOp *>(root)->transmit());
     }
 
     if (OB_FAIL(ret)) {