MDEV-34899: Make ANALYZE FORMAT=JSON print CPU statistics

PoC.
If the session has @@profiling=1, ANALYZE output will include:

  "r_profile_stats": {
    "r_user_time_ms": nnnn.nn,
    "r_system_time_ms": nnn.nn,
    "r_conext_voluntary": n,
    "r_conext_involuntary": n
  },

sql/sql_explain.cc

@@ -48,6 +48,12 @@ Explain_query::Explain_query(THD *thd_arg, MEM_ROOT *root) :
   operations(0)
 {
   optimization_time_tracker.start_tracking(stmt_thd);
+  if (thd_arg->profiling.is_enabled())
+  {
+    if ((start_profile= (PROFILE_STATS*) alloc_root(mem_root,
+                                                    sizeof(PROFILE_STATS))))
+      start_profile->collect();
+  }
 }
 
 static void print_json_array(Json_writer *writer,
@@ -277,6 +283,15 @@ int Explain_query::print_explain_json(select_result_sink *output,
     print_query_optimization_json(&writer);
   }
 
+  if (start_profile)
+  {
+    PROFILE_STATS endp;
+    endp.collect();
+    writer.add_member("r_profile_stats");
+    Json_writer_object obj(&writer);
+    endp.write_increment_json(&obj, start_profile);
+  }
+
   bool plan_found = print_query_blocks_json(&writer, is_analyze);
   writer.end_object();
 

sql/sql_explain.h

@@ -53,6 +53,8 @@ it into the slow query log.
 #ifndef SQL_EXPLAIN_INCLUDED
 #define SQL_EXPLAIN_INCLUDED
 
+#include "sql_profile.h"  /* for PROFILE_STATS */
+
 class String_list: public List<char>
 {
 public:
@@ -535,6 +537,12 @@ class Explain_query : public Sql_alloc
 #endif
 
   Exec_time_tracker optimization_time_tracker;
+
+  /*
+    if profiling=1, we are collecting the profiling data, and this holds
+    the counters taken at the query start.
+  */
+  PROFILE_STATS *start_profile= nullptr;
 };
 
 

sql/sql_profile.cc

@@ -34,6 +34,7 @@
 #include "sql_profile.h"
 #include "sql_i_s.h"                      // schema_table_store_record
 #include "sql_class.h"                    // THD
+#include "my_json_writer.h"
 
 #ifdef _WIN32
 #pragma comment(lib,"psapi.lib")
@@ -237,19 +238,10 @@ void PROF_MEASUREMENT::set_label(const char *status_arg,
   line= line_arg;
 }
 
-/**
-  This updates the statistics for this moment of time.  It captures the state
-  of the running system, so later we can compare points in time and infer what
-  happened in the mean time.  It should only be called immediately upon
-  instantiation of this PROF_MEASUREMENT.
-
-  @todo  Implement resource capture for OSes not like BSD.
-*/
-void PROF_MEASUREMENT::collect()
+void PROFILE_STATS::collect()
 {
-  time_usecs= my_interval_timer() / 1e3;  /* ns to us */
 #ifdef HAVE_GETRUSAGE
-  getrusage(RUSAGE_SELF, &rusage);
+  getrusage(RUSAGE_THREAD, &rusage);
 #elif defined(_WIN32)
   FILETIME ftDummy;
   // NOTE: Get{Process|Thread}Times has a granularity of the clock interval,
@@ -261,6 +253,20 @@ void PROF_MEASUREMENT::collect()
 #endif
 }
 
+/**
+  This updates the statistics for this moment of time.  It captures the state
+  of the running system, so later we can compare points in time and infer what
+  happened in the mean time.  It should only be called immediately upon
+  instantiation of this PROF_MEASUREMENT.
+
+  @todo  Implement resource capture for OSes not like BSD.
+*/
+void PROF_MEASUREMENT::collect()
+{
+  time_usecs= my_interval_timer() / 1e3;  /* ns to us */
+  PROFILE_STATS::collect();
+}
+
 
 QUERY_PROFILE::QUERY_PROFILE(PROFILING *profiling_arg, const char *status_arg)
   :profiling(profiling_arg), profiling_query_id(0), query_source(NULL)
@@ -688,6 +694,39 @@ int PROFILING::fill_statistics_info(THD *thd_arg, TABLE_LIST *tables, Item *cond
   DBUG_RETURN(0);
 }
 
+void PROFILE_STATS::write_increment_json(Json_writer_object *obj,
+                                         const PROFILE_STATS *prev)
+{
+#ifdef HAVE_GETRUSAGE
+  const timeval &ut_start= prev->rusage.ru_utime;
+  const timeval &ut_end= rusage.ru_utime;
+
+  double ut= (ut_end.tv_sec - ut_start.tv_sec) * 1000.0  +
+             (ut_end.tv_usec - ut_start.tv_usec) / 1000.0;
+  obj->add("r_user_time_ms", ut);
+
+  const timeval &st_start= prev->rusage.ru_stime;
+  const timeval &st_end= rusage.ru_stime;
+
+  double st= (st_end.tv_sec - st_start.tv_sec) * 1000.0  +
+             (st_end.tv_usec - st_start.tv_usec) / 1000.0;
+  obj->add("r_system_time_ms", st);
+
+  obj->add("r_context_voluntary",
+           (uint32)(rusage.ru_nvcsw - prev->rusage.ru_nvcsw));
+  obj->add("r_context_involuntary",
+           (uint32)(rusage.ru_nivcsw - prev->rusage.ru_nivcsw));
+
+#elif defined(_WIN32)
+
+  double ut= GetTimeDiffInSeconds(&ftUser, &prev->ftUser);
+  double st= GetTimeDiffInSeconds(&ftKernel, &prev->ftKernel);
+  obj->add("r_user_time_ms", ut/1000.0);
+  obj->add("r_system_time_ms", st/1000.0);
+
+#endif
+}
+
 
 void PROFILING::reset()
 {

sql/sql_profile.h

@@ -169,11 +169,26 @@ template <class T> class Queue
 
 };
 
+class Json_writer_object;
+
+class PROFILE_STATS
+{
+public:
+#ifdef HAVE_GETRUSAGE
+  struct rusage rusage;
+#elif defined(_WIN32)
+  FILETIME ftKernel, ftUser;
+  IO_COUNTERS io_count;
+  PROCESS_MEMORY_COUNTERS mem_count;
+#endif
+  void collect();
+  void write_increment_json(Json_writer_object *obj, const PROFILE_STATS *prev);
+};
 
 /**
   A single entry in a single profile.
 */
-class PROF_MEASUREMENT
+class PROF_MEASUREMENT : private PROFILE_STATS
 {
 private:
   friend class QUERY_PROFILE;
@@ -181,14 +196,6 @@ class PROF_MEASUREMENT
 
   QUERY_PROFILE *profile;
   char *status;
-#ifdef HAVE_GETRUSAGE
-  struct rusage rusage;
-#elif defined(_WIN32)
-  FILETIME ftKernel, ftUser;
-  IO_COUNTERS io_count;
-  PROCESS_MEMORY_COUNTERS mem_count;
-#endif
-
   char *function;
   char *file;
   unsigned int line;
@@ -276,6 +283,8 @@ class PROFILING
   PROFILING();
   ~PROFILING();
 
+  bool is_enabled() const { return enabled; }
+
   /**
     At a point in execution where we know the query source, save the text
     of it in the query profile.