MDEV-20854: ANALYZE for statements: not clear where the time is spent

Count the "gap" time between table accesses and display it as
r_other_time_ms in the "table" element.

* The advantage of this approach is that it doesn't add any new
  my_timer_cycles() calls.
* The disadvantage is that the definition of what is done during
  "other time" is not that clear: it includes checking the WHERE
  (for this table), constructing index lookup tuple (for the next table)
  writing to GROUP BY temporary table (as we dont account for that time
  separately [yet], etc)

11 files changed, 115 insertions, 35 deletions

diff --git a/sql/filesort.cc b/sql/filesort.cc
index 3f4291cfb1f..bd6ac9d7374 100644
--- a/sql/filesort.cc
+++ b/sql/filesort.cc
@@ -196,7 +196,7 @@ SORT_INFO *filesort(THD *thd, TABLE *table, Filesort *filesort,
   else
     thd->inc_status_sort_scan();
   thd->query_plan_flags|= QPLAN_FILESORT;
-  tracker->report_use(max_rows);
+  tracker->report_use(thd, max_rows);
 
   // If number of rows is not known, use as much of sort buffer as possible. 
   num_rows= table->file->estimate_rows_upper_bound();
@@ -364,7 +364,7 @@ SORT_INFO *filesort(THD *thd, TABLE *table, Filesort *filesort,
       outfile->end_of_file=save_pos;
     }
   }
-  tracker->report_merge_passes_at_end(thd->query_plan_fsort_passes);
+  tracker->report_merge_passes_at_end(thd, thd->query_plan_fsort_passes);
   if (unlikely(error))
   {
     int kill_errno= thd->killed_errno();
diff --git a/sql/handler.h b/sql/handler.h
index c751817f5f1..f23476242a0 100644
--- a/sql/handler.h
+++ b/sql/handler.h
@@ -5008,12 +5008,12 @@ int binlog_log_row(TABLE* table,
   { \
     Exec_time_tracker *this_tracker; \
     if (unlikely((this_tracker= tracker))) \
-      tracker->start_tracking(); \
+      tracker->start_tracking(table->in_use); \
     \
     MYSQL_TABLE_IO_WAIT(PSI, OP, INDEX, FLAGS, PAYLOAD); \
     \
     if (unlikely(this_tracker)) \
-      tracker->stop_tracking(); \
+      tracker->stop_tracking(table->in_use); \
   }
 
 void print_keydup_error(TABLE *table, KEY *key, const char *msg, myf errflag);
diff --git a/sql/sql_analyze_stmt.cc b/sql/sql_analyze_stmt.cc
index f1c6e2c73ea..fdabcf1e494 100644
--- a/sql/sql_analyze_stmt.cc
+++ b/sql/sql_analyze_stmt.cc
@@ -80,3 +80,20 @@ void Filesort_tracker::print_json_members(Json_writer *writer)
   }
 }
 
+void attach_gap_time_tracker(THD *thd, Gap_time_tracker *gap_tracker,
+                             ulonglong timeval)
+{
+  thd->gap_tracker_data.bill_to= gap_tracker;
+  thd->gap_tracker_data.start_time= timeval;
+}
+
+void process_gap_time_tracker(THD *thd, ulonglong timeval)
+{
+  if (thd->gap_tracker_data.bill_to)
+  {
+    thd->gap_tracker_data.bill_to->log_time(thd->gap_tracker_data.start_time,
+                                            timeval);
+    thd->gap_tracker_data.bill_to= NULL;
+  }
+}
+
diff --git a/sql/sql_analyze_stmt.h b/sql/sql_analyze_stmt.h
index eec52822ae5..9d5151c3be2 100644
--- a/sql/sql_analyze_stmt.h
+++ b/sql/sql_analyze_stmt.h
@@ -38,6 +38,10 @@ $stmt").
 
 */
 
+class Gap_time_tracker;
+void attach_gap_time_tracker(THD *thd, Gap_time_tracker *gap_tracker, ulonglong timeval);
+void process_gap_time_tracker(THD *thd, ulonglong timeval);
+
 /*
   A class for tracking time it takes to do a certain action
 */
@@ -48,26 +52,37 @@ protected:
   ulonglong cycles;
   ulonglong last_start;
 
-  void cycles_stop_tracking()
+  void cycles_stop_tracking(THD *thd)
   {
     ulonglong end= my_timer_cycles();
     cycles += end - last_start;
     if (unlikely(end < last_start))
       cycles += ULONGLONG_MAX;
+
+    process_gap_time_tracker(thd, end);
+    if (my_gap_tracker)
+      attach_gap_time_tracker(thd, my_gap_tracker, end);
   }
 public:
-  Exec_time_tracker() : count(0), cycles(0) {}
-  
+  Exec_time_tracker() : count(0), cycles(0), my_gap_tracker(NULL) {}
+
+  /*
+    The time spent between stop_tracking() call on this object and any
+    other time measurement will be billed to this tracker.
+  */
+  Gap_time_tracker *my_gap_tracker;
+
   // interface for collecting time
-  void start_tracking()
+  void start_tracking(THD *thd)
   {
     last_start= my_timer_cycles();
+    process_gap_time_tracker(thd, last_start);
   }
 
-  void stop_tracking()
+  void stop_tracking(THD *thd)
   {
     count++;
-    cycles_stop_tracking();
+    cycles_stop_tracking(thd);
   }
 
   // interface for getting the time
@@ -81,6 +96,31 @@ public:
 
 
 /*
+  Tracker for time spent between the calls to Exec_time_tracker's {start|
+  stop}_tracking().
+
+  @seealso Gap_time_tracker_data in sql_class.h
+*/
+class Gap_time_tracker
+{
+  ulonglong cycles;
+public:
+  Gap_time_tracker() : cycles(0) {}
+
+  void log_time(ulonglong start, ulonglong end) {
+    cycles += end - start;
+  }
+
+  double get_time_ms() const
+  {
+    // convert 'cycles' to milliseconds.
+    return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency;
+  }
+};
+
+
+
+/*
   A class for counting certain actions (in all queries), and optionally
   collecting the timings (in ANALYZE queries).
 */
@@ -99,22 +139,22 @@ public:
   /*
     Unlike Exec_time_tracker::stop_tracking, we don't increase loops.
   */
-  void stop_tracking()
+  void stop_tracking(THD *thd)
   {
-    cycles_stop_tracking();
+    cycles_stop_tracking(thd);
   }
 };
 
-#define ANALYZE_START_TRACKING(tracker) \
+#define ANALYZE_START_TRACKING(thd, tracker) \
   { \
     (tracker)->incr_loops(); \
     if (unlikely((tracker)->timed)) \
-    { (tracker)->start_tracking(); } \
+    { (tracker)->start_tracking(thd); } \
   }
 
-#define ANALYZE_STOP_TRACKING(tracker) \
+#define ANALYZE_STOP_TRACKING(thd, tracker) \
   if (unlikely((tracker)->timed)) \
-  { (tracker)->stop_tracking(); }
+  { (tracker)->stop_tracking(thd); }
 
 /*
   A class for collecting read statistics.
@@ -186,14 +226,14 @@ public:
   
   /* Functions that filesort uses to report various things about its execution */
 
-  inline void report_use(ha_rows r_limit_arg)
+  inline void report_use(THD *thd, ha_rows r_limit_arg)
   {
     if (!time_tracker.get_loops())
       r_limit= r_limit_arg;
     else
       r_limit= (r_limit != r_limit_arg)? 0: r_limit_arg;
 
-    ANALYZE_START_TRACKING(&time_tracker);
+    ANALYZE_START_TRACKING(thd, &time_tracker);
   }
   inline void incr_pq_used() { r_used_pq++; }
 
@@ -210,9 +250,9 @@ public:
   {
     sort_passes -= passes;
   }
-  inline void report_merge_passes_at_end(ulong passes)
+  inline void report_merge_passes_at_end(THD *thd, ulong passes)
   {
-    ANALYZE_STOP_TRACKING(&time_tracker);
+    ANALYZE_STOP_TRACKING(thd, &time_tracker);
     sort_passes += passes;
   }
 
@@ -318,14 +358,14 @@ public:
     container_elements(0), n_checks(0), n_positive_checks(0)
   {}
 
-  inline void start_tracking()
+  inline void start_tracking(THD *thd)
   {
-    ANALYZE_START_TRACKING(&time_tracker);
+    ANALYZE_START_TRACKING(thd, &time_tracker);
   }
 
-  inline void stop_tracking()
+  inline void stop_tracking(THD *thd)
   {
-    ANALYZE_STOP_TRACKING(&time_tracker);
+    ANALYZE_STOP_TRACKING(thd, &time_tracker);
   }
 
   /* Save container buffer size in bytes */
diff --git a/sql/sql_class.cc b/sql/sql_class.cc
index cc572065e92..0aca810692e 100644
--- a/sql/sql_class.cc
+++ b/sql/sql_class.cc
@@ -1336,6 +1336,7 @@ void THD::init()
 #endif //EMBEDDED_LIBRARY
 
   apc_target.init(&LOCK_thd_kill);
+  gap_tracker_data.init();
   DBUG_VOID_RETURN;
 }
 
diff --git a/sql/sql_class.h b/sql/sql_class.h
index 2fb5797b325..0618bbdccbf 100644
--- a/sql/sql_class.h
+++ b/sql/sql_class.h
@@ -2141,6 +2141,22 @@ struct wait_for_commit
 extern "C" void my_message_sql(uint error, const char *str, myf MyFlags);
 
 
+class Gap_time_tracker;
+
+/*
+  Thread context for Gap_time_tracker class.
+*/
+class Gap_time_tracker_data
+{
+public:
+  Gap_time_tracker_data(): bill_to(NULL) {}
+
+  Gap_time_tracker *bill_to;
+  ulonglong start_time;
+
+  void init() { bill_to = NULL; }
+};
+
 /**
   A wrapper around thread_count.
 
@@ -3326,6 +3342,7 @@ public:
   */
   Apc_target apc_target;
 
+  Gap_time_tracker_data gap_tracker_data;
 #ifndef MYSQL_CLIENT
   enum enum_binlog_query_type {
     /* The query can be logged in row format or in statement format. */
diff --git a/sql/sql_delete.cc b/sql/sql_delete.cc
index 0ea00a7d61c..b12312041bd 100644
--- a/sql/sql_delete.cc
+++ b/sql/sql_delete.cc
@@ -600,7 +600,7 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
   
   if (!(explain= query_plan.save_explain_delete_data(thd->mem_root, thd)))
     goto got_error;
-  ANALYZE_START_TRACKING(&explain->command_tracker);
+  ANALYZE_START_TRACKING(thd, &explain->command_tracker);
 
   DBUG_EXECUTE_IF("show_explain_probe_delete_exec_start", 
                   dbug_serve_apcs(thd, 1););
@@ -878,7 +878,7 @@ terminate_delete:
     table->file->ha_release_auto_increment();
   if (options & OPTION_QUICK)
     (void) table->file->extra(HA_EXTRA_NORMAL);
-  ANALYZE_STOP_TRACKING(&explain->command_tracker);
+  ANALYZE_STOP_TRACKING(thd, &explain->command_tracker);
 
 cleanup:
   /*
diff --git a/sql/sql_explain.cc b/sql/sql_explain.cc
index d3b85638898..da727ba54fc 100644
--- a/sql/sql_explain.cc
+++ b/sql/sql_explain.cc
@@ -1811,10 +1811,11 @@ void Explain_table_access::print_explain_json(Explain_query *query,
       double total_time= op_tracker.get_time_ms();
       if (rowid_filter)
         total_time+= rowid_filter->tracker->get_time_fill_container_ms();
-      writer->add_member("r_total_time_ms").add_double(total_time);
+      writer->add_member("r_table_time_ms").add_double(total_time);
+      writer->add_member("r_other_time_ms").add_double(extra_time_tracker.get_time_ms());
     }
   }
-  
+
   /* `filtered` */
   if (filtered_set)
     writer->add_member("filtered").add_double(filtered);
diff --git a/sql/sql_explain.h b/sql/sql_explain.h
index 3896636f9fd..bd8c8a4d499 100644
--- a/sql/sql_explain.h
+++ b/sql/sql_explain.h
@@ -835,6 +835,8 @@ public:
   /* Tracker for reading the table */
   Table_access_tracker tracker;
   Exec_time_tracker op_tracker;
+  Gap_time_tracker extra_time_tracker;
+
   Table_access_tracker jbuf_tracker;
   
   Explain_rowid_filter *rowid_filter;
diff --git a/sql/sql_select.cc b/sql/sql_select.cc
index 268fec84e3b..38f5b7a5a44 100644
--- a/sql/sql_select.cc
+++ b/sql/sql_select.cc
@@ -4168,9 +4168,9 @@ void JOIN::exec()
                                                select_lex->select_number))
                         dbug_serve_apcs(thd, 1);
                  );
-  ANALYZE_START_TRACKING(&explain->time_tracker);
+  ANALYZE_START_TRACKING(thd, &explain->time_tracker);
   exec_inner();
-  ANALYZE_STOP_TRACKING(&explain->time_tracker);
+  ANALYZE_STOP_TRACKING(thd, &explain->time_tracker);
 
   DBUG_EXECUTE_IF("show_explain_probe_join_exec_end", 
                   if (dbug_user_var_equals_int(thd, 
@@ -13139,7 +13139,7 @@ void JOIN_TAB::build_range_rowid_filter_if_needed()
     Exec_time_tracker *table_tracker= table->file->get_time_tracker();
     Rowid_filter_tracker *rowid_tracker= rowid_filter->get_tracker();
     table->file->set_time_tracker(rowid_tracker->get_time_tracker());
-    rowid_tracker->start_tracking();
+    rowid_tracker->start_tracking(join->thd);
     if (!rowid_filter->build())
     {
       is_rowid_filter_built= true;
@@ -13149,7 +13149,7 @@ void JOIN_TAB::build_range_rowid_filter_if_needed()
       delete rowid_filter;
       rowid_filter= 0;
     }
-    rowid_tracker->stop_tracking();
+    rowid_tracker->stop_tracking(join->thd);
     table->file->set_time_tracker(table_tracker);
   }
 }
@@ -26076,8 +26076,10 @@ bool JOIN_TAB::save_explain_data(Explain_table_access *eta,
 
   /* Enable the table access time tracker only for "ANALYZE stmt" */
   if (thd->lex->analyze_stmt)
+  {
     table->file->set_time_tracker(&eta->op_tracker);
-
+    eta->op_tracker.my_gap_tracker = &eta->extra_time_tracker;
+  }
   /* No need to save id and select_type here, they are kept in Explain_select */
 
   /* table */
diff --git a/sql/sql_update.cc b/sql/sql_update.cc
index 9f298a51b72..26dfe5e40a2 100644
--- a/sql/sql_update.cc
+++ b/sql/sql_update.cc
@@ -666,7 +666,7 @@ int mysql_update(THD *thd,
   if (!(explain= query_plan.save_explain_update_data(query_plan.mem_root, thd)))
     goto err;
 
-  ANALYZE_START_TRACKING(&explain->command_tracker);
+  ANALYZE_START_TRACKING(thd, &explain->command_tracker);
 
   DBUG_EXECUTE_IF("show_explain_probe_update_exec_start", 
                   dbug_serve_apcs(thd, 1););
@@ -1168,7 +1168,7 @@ update_begin:
       break;
     }
   }
-  ANALYZE_STOP_TRACKING(&explain->command_tracker);
+  ANALYZE_STOP_TRACKING(thd, &explain->command_tracker);
   table->auto_increment_field_not_null= FALSE;
   dup_key_found= 0;
   /*