MDEV-7648: Extra data in ANALYZE FORMAT=JSON $stmt

Show total execution time (r_total_time_ms) for various parts of the
query:
1. time spent in SELECTs
2. time spent reading rows from storage engines

#2 currently gets the data from P_S.

6 files changed, 137 insertions, 3 deletions

diff --git a/sql/mysqld.cc b/sql/mysqld.cc
index 2e6d88ef0a4..cde920a3678 100644
--- a/sql/mysqld.cc
+++ b/sql/mysqld.cc
@@ -314,6 +314,9 @@ arg_cmp_func Arg_comparator::comparator_matrix[6][2] =
  {&Arg_comparator::compare_decimal,    &Arg_comparator::compare_e_decimal},
  {&Arg_comparator::compare_datetime,   &Arg_comparator::compare_e_datetime}};
 
+/* Timer info to be used by the SQL layer */
+MY_TIMER_INFO sys_timer_info;
+
 /* static variables */
 
 #ifdef HAVE_PSI_INTERFACE
@@ -5458,6 +5461,7 @@ int mysqld_main(int argc, char **argv)
 #ifdef WITH_PERFSCHEMA_STORAGE_ENGINE
   pfs_param.m_pfs_instrument= const_cast<char*>("");
 #endif /* WITH_PERFSCHEMA_STORAGE_ENGINE */
+  my_timer_init(&sys_timer_info);
 
   int ho_error __attribute__((unused))= handle_early_options();
 
diff --git a/sql/mysqld.h b/sql/mysqld.h
index bfce719a280..b414e5168b2 100644
--- a/sql/mysqld.h
+++ b/sql/mysqld.h
@@ -26,6 +26,7 @@
 #include "sql_cmd.h"
 #include <my_rnd.h>
 #include "my_pthread.h"
+#include "my_rdtsc.h"
 
 class THD;
 struct handlerton;
@@ -60,6 +61,8 @@ typedef Bitmap<((MAX_INDEXES+7)/8*8)> key_map; /* Used for finding keys */
 #define OPT_SESSION SHOW_OPT_SESSION
 #define OPT_GLOBAL SHOW_OPT_GLOBAL
 
+extern MY_TIMER_INFO sys_timer_info;
+
 /*
   Values for --slave-parallel-mode
   Must match order in slave_parallel_mode_typelib in sys_vars.cc.
diff --git a/sql/sql_explain.cc b/sql/sql_explain.cc
index aa16a744e83..873ed74a1a2 100644
--- a/sql/sql_explain.cc
+++ b/sql/sql_explain.cc
@@ -732,7 +732,12 @@ void Explain_select::print_explain_json(Explain_query *query,
     */
     writer->add_member("query_block").start_object();
     writer->add_member("select_id").add_ll(select_id);
-    
+     
+    if (is_analyze && time_tracker.get_loops())
+    {
+      writer->add_member("r_loops").add_ll(time_tracker.get_loops());
+      writer->add_member("r_total_time_ms").add_double(time_tracker.get_time_ms());
+    }
     if (exec_const_cond)
     {
       writer->add_member("const_condition");
@@ -1289,6 +1294,9 @@ void Explain_table_access::print_explain_json(Explain_query *query,
     }
     else
       writer->add_null();
+
+    op_tracker.end_tracking();
+    op_tracker.print_json(writer);
   }
   
   /* `filtered` */
@@ -1971,3 +1979,40 @@ void create_explain_query_if_not_exists(LEX *lex, MEM_ROOT *mem_root)
     create_explain_query(lex, mem_root);
 }
 
+//////////////////////////////////////////////////////////////////////////////
+// 
+//////////////////////////////////////////////////////////////////////////////
+
+void Table_op_tracker::start_tracking(TABLE *table)
+{
+  //TODO: will this compile without P_S ?
+  start_count= end_count= 0;
+  if ((psi_table= table->file->m_psi))
+  {
+    PSI_CALL_get_table_current_stats(psi_table, &start_count, &start_sum);
+  }
+}
+
+
+void Table_op_tracker::end_tracking()
+{
+  if (psi_table)
+  {
+    PSI_CALL_get_table_current_stats(psi_table, &end_count, &end_sum);
+  }
+}
+
+void Table_op_tracker::print_json(Json_writer *writer)
+{
+  if (start_count != end_count)
+  {
+    /*
+      We have time in picoseconds, we want to print in milli-seconds
+       picosecond is sec* 10^ -12
+       millisecond is sec * 10^-3
+    */
+    double ms= double(end_sum - start_sum) / 1e9;
+    writer->add_member("r_total_time_ms").add_double(ms);
+  }
+}
+
diff --git a/sql/sql_explain.h b/sql/sql_explain.h
index 970edf7800d..98b56ed88c0 100644
--- a/sql/sql_explain.h
+++ b/sql/sql_explain.h
@@ -21,12 +21,16 @@ public:
   bool append_str(MEM_ROOT *mem_root, const char *str);
 };
 
+class Json_writer;
 
 /*
   A class for collecting read statistics.
   
   The idea is that we run several scans. Each scans gets rows, and then filters
   some of them out.  We count scans, rows, and rows left after filtering.
+
+  (note: at the moment, the class is not actually tied to a physical table. 
+   It can be used to track reading from files, buffers, etc).
 */
 
 class Table_access_tracker 
@@ -66,6 +70,72 @@ public:
 };
 
 
+/*
+  A class to track operations (currently, row reads) on a PSI_table.
+*/
+class Table_op_tracker
+{
+  PSI_table *psi_table;
+
+  /* Table counter values at start. Sum is in picoseconds */
+  ulonglong start_sum;
+  ulonglong start_count;
+
+  /* Table counter values at end */
+  ulonglong end_sum;
+  ulonglong end_count;
+public:
+  void start_tracking(TABLE *table);
+  // At the moment, print_json will call end_tracking.
+  void end_tracking();
+
+  // this may print nothing if the table was not tracked.
+  void print_json(Json_writer *writer);
+};
+
+
+#define ANALYZE_START_TRACKING(tracker) \
+  if (tracker) \
+  { tracker->start_tracking(); }
+
+#define ANALYZE_STOP_TRACKING(tracker) \
+  if (tracker) \
+  { tracker->stop_tracking(); }
+
+/*
+  A class for tracking execution time
+*/
+class Exec_time_tracker
+{
+  ulonglong count;
+  ulonglong cycles;
+  ulonglong last_start;
+public:
+  Exec_time_tracker() : count(0), cycles(0) {}
+  
+  // interface for collecting time
+  void start_tracking()
+  {
+    last_start= my_timer_cycles();
+  }
+
+  void stop_tracking()
+  {
+    ulonglong last_end= my_timer_cycles();
+    count++;
+    cycles += last_end - last_start;
+  }
+
+  // interface for getting the time
+  //loops, starts, stops
+  ulonglong get_loops() { return count; }
+  double get_time_ms()
+  {
+    // convert 'cycles' to milliseconds.
+    return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency;
+  }
+};
+
 /**************************************************************************************
  
   Data structures for producing EXPLAIN outputs.
@@ -82,8 +152,6 @@ const int FAKE_SELECT_LEX_ID= (int)UINT_MAX;
 
 class Explain_query;
 
-class Json_writer;
-
 /* 
   A node can be either a SELECT, or a UNION.
 */
@@ -231,6 +299,9 @@ public:
   /* Global join attributes. In tabular form, they are printed on the first row */
   bool using_temporary;
   bool using_filesort;
+
+  /* ANALYZE members */
+  Exec_time_tracker time_tracker;
   
   int print_explain(Explain_query *query, select_result_sink *output, 
                     uint8 explain_flags, bool is_analyze);
@@ -666,6 +737,7 @@ public:
 
   /* Tracker for reading the table */
   Table_access_tracker tracker;
+  Table_op_tracker op_tracker;
   Table_access_tracker jbuf_tracker;
 
   int print_explain(select_result_sink *output, uint8 explain_flags, 
@@ -735,6 +807,7 @@ public:
 
   /* ANALYZE members and methods */
   Table_access_tracker tracker;
+  //psergey-todo: io-tracker here.
 
   virtual int print_explain(Explain_query *query, select_result_sink *output, 
                             uint8 explain_flags, bool is_analyze);
diff --git a/sql/sql_select.cc b/sql/sql_select.cc
index de713d6aca0..6c7e762b088 100644
--- a/sql/sql_select.cc
+++ b/sql/sql_select.cc
@@ -2390,7 +2390,9 @@ void JOIN::exec()
                                                select_lex->select_number))
                         dbug_serve_apcs(thd, 1);
                  );
+  ANALYZE_START_TRACKING(tracker);
   exec_inner();
+  ANALYZE_STOP_TRACKING(tracker);
 
   DBUG_EXECUTE_IF("show_explain_probe_join_exec_end", 
                   if (dbug_user_var_equals_int(thd, 
@@ -23417,6 +23419,7 @@ void JOIN_TAB::save_explain_data(Explain_table_access *eta, table_map prefix_tab
   tab->tracker= &eta->tracker;
   tab->jbuf_tracker= &eta->jbuf_tracker;
   
+  eta->op_tracker.start_tracking(table);
   /* id and select_type are kept in Explain_select */
 
   /* table */
@@ -23855,6 +23858,7 @@ int JOIN::save_explain_data_intern(Explain_query *output, bool need_tmp_table,
     Explain_select *xpl_sel;
     explain_node= xpl_sel= new (output->mem_root) Explain_select(output->mem_root);
     table_map used_tables=0;
+    tracker= &xpl_sel->time_tracker;
 
     join->select_lex->set_explain_type(true);
     xpl_sel->select_id= join->select_lex->select_number;
diff --git a/sql/sql_select.h b/sql/sql_select.h
index a50ed130df8..7cff7912a0b 100644
--- a/sql/sql_select.h
+++ b/sql/sql_select.h
@@ -252,6 +252,7 @@ typedef struct st_join_table {
   enum explain_extra_tag info;
   
   Table_access_tracker *tracker;
+
   Table_access_tracker *jbuf_tracker;
   /* 
     Bitmap of TAB_INFO_* bits that encodes special line for EXPLAIN 'Extra'
@@ -1260,6 +1261,8 @@ public:
                                  OPTIMIZATION_DONE=2};
   bool optimized; ///< flag to avoid double optimization in EXPLAIN
   bool initialized; ///< flag to avoid double init_execution calls
+
+  Exec_time_tracker *tracker;
   
   enum { QEP_NOT_PRESENT_YET, QEP_AVAILABLE, QEP_DELETED} have_query_plan;
 
@@ -1354,6 +1357,8 @@ public:
     no_rows_in_result_called= 0;
     positions= best_positions= 0;
 
+    tracker= NULL;
+
     all_fields= fields_arg;
     if (&fields_list != &fields_arg)      /* Avoid valgrind-warning */
       fields_list= fields_arg;