[CP] SQL execution time consumption statistics

deps/oblib/src/lib/statistic_event/ob_stat_event.h

@@ -147,11 +147,8 @@ STAT_EVENT_ADD_DEF(SQL_OPEN_CURSORS_CURRENT, "opened cursors current", ObStatCla
 STAT_EVENT_ADD_DEF(SQL_OPEN_CURSORS_CUMULATIVE, "opened cursors cumulative", ObStatClassIds::SQL, "opened cursors cumulative", 40031, true, true)
 
 STAT_EVENT_ADD_DEF(SQL_LOCAL_COUNT, "sql local count", ObStatClassIds::SQL, "sql local count", 40010, true, true)
-//STAT_EVENT_ADD_DEF(SQL_LOCAL_TIME, "SQL_LOCAL_TIME", SQL, "SQL_LOCAL_TIME")
 STAT_EVENT_ADD_DEF(SQL_REMOTE_COUNT, "sql remote count", ObStatClassIds::SQL, "sql remote count", 40011, true, true)
-//STAT_EVENT_ADD_DEF(SQL_REMOTE_TIME, "SQL_REMOTE_TIME", SQL, "SQL_REMOTE_TIME")
 STAT_EVENT_ADD_DEF(SQL_DISTRIBUTED_COUNT, "sql distributed count", ObStatClassIds::SQL, "sql distributed count", 40012, true, true)
-//STAT_EVENT_ADD_DEF(SQL_DISTRIBUTED_TIME, "SQL_DISTRIBUTED_TIME", SQL, "SQL_DISTRIBUTED_TIME")
 STAT_EVENT_ADD_DEF(ACTIVE_SESSIONS, "active sessions", ObStatClassIds::SQL, "active sessions", 40013, false, true)
 STAT_EVENT_ADD_DEF(SQL_SINGLE_QUERY_COUNT, "single query count", ObStatClassIds::SQL, "single query count", 40014, true, true)
 STAT_EVENT_ADD_DEF(SQL_MULTI_QUERY_COUNT, "multiple query count", ObStatClassIds::SQL, "multiple query count", 40015, true, true)
@@ -173,6 +170,10 @@ STAT_EVENT_ADD_DEF(SQL_USER_LOGONS_CUMULATIVE, "user logons cumulative", ObStatC
 STAT_EVENT_ADD_DEF(SQL_USER_LOGOUTS_CUMULATIVE, "user logouts cumulative", ObStatClassIds::SQL, "user logouts cumulative", 40113, true, true)
 STAT_EVENT_ADD_DEF(SQL_USER_LOGONS_FAILED_CUMULATIVE, "user logons failed cumulative", ObStatClassIds::SQL, "user logons failed cumulative", 40114, true, true)
 STAT_EVENT_ADD_DEF(SQL_USER_LOGONS_COST_TIME_CUMULATIVE, "user logons time cumulative", ObStatClassIds::SQL, "user logons time cumulative", 40115, true, true)
+STAT_EVENT_ADD_DEF(SQL_LOCAL_TIME, "sql local execute time", ObStatClassIds::SQL, "sql local execute time", 40116, true, true)
+STAT_EVENT_ADD_DEF(SQL_REMOTE_TIME, "sql remote execute time", ObStatClassIds::SQL, "sql remote execute time", 40117, true, true)
+STAT_EVENT_ADD_DEF(SQL_DISTRIBUTED_TIME, "sql distributed execute time", ObStatClassIds::SQL, "sql distributed execute time", 40118, true, true)
+
 // CACHE
 STAT_EVENT_ADD_DEF(ROW_CACHE_HIT, "row cache hit", ObStatClassIds::CACHE, "row cache hit", 50000, true, true)
 STAT_EVENT_ADD_DEF(ROW_CACHE_MISS, "row cache miss", ObStatClassIds::CACHE, "row cache miss", 50001, true, true)

src/observer/mysql/obmp_query.cpp

@@ -862,6 +862,11 @@ OB_INLINE int ObMPQuery::do_process(ObSQLSessionInfo &session,
         // even though sql audit disabled
         update_audit_info(total_wait_desc, audit_record);
       }
+      if (enable_perf_event && !THIS_THWORKER.need_retry()
+        && OB_NOT_NULL(result.get_physical_plan())) {
+        const int64_t time_cost = exec_end_timestamp_ - get_receive_timestamp();
+        ObSQLUtils::record_execute_time(result.get_physical_plan()->get_plan_type(), time_cost);
+      }
       // 重试需要满足一下条件：
       // 1. rs.open 执行失败
       // 2. 没有给客户端返回结果，本次执行没有副作用

src/observer/mysql/obmp_query.h

@@ -90,6 +90,7 @@ private:
 
 
   void record_stat(const sql::stmt::StmtType type, const int64_t end_time) const;
+  void record_execute_time(const sql::ObPhysicalPlan *plan, const int64_t end_time) const;
   void update_audit_info(const ObWaitEventStat &total_wait_desc,
                          ObAuditRecordData &record);
   int fill_feedback_session_info(ObMySQLResultSet &result,

src/observer/mysql/obmp_stmt_execute.cpp

@@ -1190,6 +1190,11 @@ int ObMPStmtExecute::do_process(ObSQLSessionInfo &session,
         exec_end_timestamp_ = ObTimeUtility::current_time();
         record_stat(result.get_stmt_type(), exec_end_timestamp_);
       }
+      if (enable_perf_event && !THIS_THWORKER.need_retry()
+        && OB_NOT_NULL(result.get_physical_plan())) {
+        const int64_t time_cost = exec_end_timestamp_ - get_receive_timestamp();
+        ObSQLUtils::record_execute_time(result.get_physical_plan()->get_plan_type(), time_cost);
+      }
       if (enable_sql_audit) {
         audit_record.exec_record_.record_end(di);
         bool first_record = (1 == audit_record.try_cnt_);

src/observer/mysql/obmp_stmt_execute.h

@@ -146,6 +146,7 @@ protected:
   sql::ObSqlCtx &get_ctx() { return ctx_; }
   ObQueryRetryCtrl &get_retry_ctrl() { return retry_ctrl_; }
   void record_stat(const sql::stmt::StmtType type, const int64_t end_time) const;
+  void record_execute_time(const sql::ObPhysicalPlan *plan, const int64_t end_time) const;
   int request_params(sql::ObSQLSessionInfo *session,
                      const char* &pos,
                      uint32_t ps_stmt_checksum,

src/observer/ob_inner_sql_connection.cpp

@@ -584,6 +584,10 @@ int ObInnerSQLConnection::process_record(sql::ObResultSet &result_set,
     }
 
     record_stat(session, result_set.get_stmt_type(), is_from_pl);
+    if (lib::is_diagnose_info_enabled() && OB_NOT_NULL(result_set.get_physical_plan())) {
+      const int64_t time_cost = ObTimeUtility::current_time() - session.get_query_start_time();
+      ObSQLUtils::record_execute_time(result_set.get_physical_plan()->get_plan_type(), time_cost);
+    }
     ObSQLUtils::handle_audit_record(false, sql::PSCursor == exec_timestamp.exec_type_
                                                   ? EXECUTE_PS_EXECUTE :
                                                   (is_from_pl ? EXECUTE_PL_EXECUTE : EXECUTE_INNER),

src/observer/ob_inner_sql_connection.h

@@ -309,6 +309,9 @@ public:
                                const bool is_oracle_mode,
                                const bool is_ddl);
 
+  static void record_execute_time(sql::ObSQLSessionInfo& session,
+                                  const sql::ObPhysicalPlan *plan);
+
   int64_t get_init_timestamp() const { return init_timestamp_; }
 
 public:

src/sql/ob_sql_utils.cpp

@@ -3966,6 +3966,23 @@ int64_t ObSqlFatalErrExtraInfoGuard::to_string(char *buf, const int64_t buf_len)
   return pos;
 }
 
+void ObSQLUtils::record_execute_time(const ObPhyPlanType type,
+                                     const int64_t time_cost)
+{
+  #define ADD_EXECUTE_TIME(type)                  \
+    case OB_PHY_PLAN_##type:                      \
+      EVENT_ADD(SQL_##type##_TIME, time_cost);    \
+      break
+  switch(type)
+  {
+    ADD_EXECUTE_TIME(LOCAL);
+    ADD_EXECUTE_TIME(REMOTE);
+    ADD_EXECUTE_TIME(DISTRIBUTED);
+    default: {}
+  }
+  #undef ADD_EXECUTE_TIME
+}
+
 int ObSQLUtils::handle_audit_record(bool need_retry,
                                     const ObExecuteMode exec_mode,
                                     ObSQLSessionInfo &session,

src/sql/ob_sql_utils.h

@@ -495,6 +495,8 @@ public:
                                                   common::ObCollationType connection_collation,
                                                   const share::schema::ObViewSchema &view_schema,
                                                   common::ObString &view_definition);
+  static void record_execute_time(const ObPhyPlanType type,
+                                  const int64_t time_cost);
   static int handle_audit_record(bool need_retry,
                                  const ObExecuteMode exec_mode,
                                  ObSQLSessionInfo &session,