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

Switch from relying on PERFORMANCE_SCHEMA to using our
own hooks for counting the time spent reading rows from
tables.

8 files changed, 117 insertions, 109 deletions

diff --git a/sql/CMakeLists.txt b/sql/CMakeLists.txt
index c78fa73bb51..6dbad5c4af1 100644
--- a/sql/CMakeLists.txt
+++ b/sql/CMakeLists.txt
@@ -104,6 +104,7 @@ SET (SQL_SOURCE
 
                # added in MariaDB:
                sql_explain.h sql_explain.cc
+               sql_analyze_stmt.h
                sql_lifo_buffer.h sql_join_cache.h sql_join_cache.cc
                create_options.cc multi_range_read.cc
                opt_index_cond_pushdown.cc opt_subselect.cc
diff --git a/sql/handler.cc b/sql/handler.cc
index 7c70babfea8..4cd8d8e9aa1 100644
--- a/sql/handler.cc
+++ b/sql/handler.cc
@@ -43,6 +43,8 @@
 #include "debug_sync.h"         // DEBUG_SYNC
 #include "sql_audit.h"
 
+#include "sql_analyze_stmt.h"   // tracker in TABLE_IO_WAIT
+
 #ifdef WITH_PARTITION_STORAGE_ENGINE
 #include "ha_partition.h"
 #endif
@@ -54,6 +56,17 @@
 #include "wsrep_mysqld.h"
 #include "wsrep.h"
 
+#define TABLE_IO_WAIT(TRACKER, PSI, OP, INDEX, FLAGS, PAYLOAD) \
+  { \
+    if (unlikely(tracker)) \
+      tracker->start_tracking(); \
+    \
+    MYSQL_TABLE_IO_WAIT(PSI, OP, INDEX, FLAGS, PAYLOAD); \
+    \
+    if (unlikely(tracker)) \
+      tracker->stop_tracking(); \
+  }
+
 /*
   While we have legacy_db_type, we have this array to
   check for dups and to find handlerton from legacy_db_type.
@@ -2560,12 +2573,38 @@ int handler::ha_close(void)
     status_var_add(table->in_use->status_var.rows_tmp_read, rows_tmp_read);
   PSI_CALL_close_table(m_psi);
   m_psi= NULL; /* instrumentation handle, invalid after close_table() */
+
+  /* Detach from ANALYZE tracker */
+  tracker= NULL;
   
   DBUG_ASSERT(m_lock_type == F_UNLCK);
   DBUG_ASSERT(inited == NONE);
   DBUG_RETURN(close());
 }
 
+inline int handler::ha_write_tmp_row(uchar *buf)
+{
+  int error;
+  MYSQL_INSERT_ROW_START(table_share->db.str, table_share->table_name.str);
+  increment_statistics(&SSV::ha_tmp_write_count);
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0,
+                { error= write_row(buf); })
+  MYSQL_INSERT_ROW_DONE(error);
+  return error;
+}
+
+inline int handler::ha_update_tmp_row(const uchar *old_data, uchar *new_data)
+{
+  int error;
+  MYSQL_UPDATE_ROW_START(table_share->db.str, table_share->table_name.str);
+  increment_statistics(&SSV::ha_tmp_update_count);
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0,
+                { error= update_row(old_data, new_data);})
+  MYSQL_UPDATE_ROW_DONE(error);
+  return error;
+}
+
+
 int handler::ha_rnd_next(uchar *buf)
 {
   int result;
@@ -2574,7 +2613,7 @@ int handler::ha_rnd_next(uchar *buf)
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited == RND);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0,
     { result= rnd_next(buf); })
   if (!result)
   {
@@ -2599,7 +2638,7 @@ int handler::ha_rnd_pos(uchar *buf, uchar *pos)
   /* TODO: Find out how to solve ha_rnd_pos when finding duplicate update. */
   /* DBUG_ASSERT(inited == RND); */
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0,
     { result= rnd_pos(buf, pos); })
   increment_statistics(&SSV::ha_read_rnd_count);
   if (!result)
@@ -2618,7 +2657,7 @@ int handler::ha_index_read_map(uchar *buf, const uchar *key,
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited==INDEX);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
     { result= index_read_map(buf, key, keypart_map, find_flag); })
   increment_statistics(&SSV::ha_read_key_count);
   if (!result)
@@ -2642,7 +2681,7 @@ int handler::ha_index_read_idx_map(uchar *buf, uint index, const uchar *key,
   DBUG_ASSERT(table_share->tmp_table != NO_TMP_TABLE ||
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(end_range == NULL);
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, index, 0,
     { result= index_read_idx_map(buf, index, key, keypart_map, find_flag); })
   increment_statistics(&SSV::ha_read_key_count);
   if (!result)
@@ -2662,7 +2701,7 @@ int handler::ha_index_next(uchar * buf)
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited==INDEX);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
     { result= index_next(buf); })
   increment_statistics(&SSV::ha_read_next_count);
   if (!result)
@@ -2679,7 +2718,7 @@ int handler::ha_index_prev(uchar * buf)
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited==INDEX);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
     { result= index_prev(buf); })
   increment_statistics(&SSV::ha_read_prev_count);
   if (!result)
@@ -2695,7 +2734,7 @@ int handler::ha_index_first(uchar * buf)
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited==INDEX);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
     { result= index_first(buf); })
   increment_statistics(&SSV::ha_read_first_count);
   if (!result)
@@ -2711,7 +2750,7 @@ int handler::ha_index_last(uchar * buf)
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited==INDEX);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
     { result= index_last(buf); })
   increment_statistics(&SSV::ha_read_last_count);
   if (!result)
@@ -2727,7 +2766,7 @@ int handler::ha_index_next_same(uchar *buf, const uchar *key, uint keylen)
               m_lock_type != F_UNLCK);
   DBUG_ASSERT(inited==INDEX);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0,
     { result= index_next_same(buf, key, keylen); })
   increment_statistics(&SSV::ha_read_next_count);
   if (!result)
@@ -5852,7 +5891,7 @@ int handler::ha_write_row(uchar *buf)
   mark_trx_read_write();
   increment_statistics(&SSV::ha_write_count);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0,
                       { error= write_row(buf); })
 
   MYSQL_INSERT_ROW_DONE(error);
@@ -5885,7 +5924,7 @@ int handler::ha_update_row(const uchar *old_data, uchar *new_data)
   mark_trx_read_write();
   increment_statistics(&SSV::ha_update_count);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0,
                       { error= update_row(old_data, new_data);})
 
   MYSQL_UPDATE_ROW_DONE(error);
@@ -5913,7 +5952,7 @@ int handler::ha_delete_row(const uchar *buf)
   mark_trx_read_write();
   increment_statistics(&SSV::ha_delete_count);
 
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_DELETE_ROW, active_index, 0,
+  TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_DELETE_ROW, active_index, 0,
     { error= delete_row(buf);})
   MYSQL_DELETE_ROW_DONE(error);
   if (unlikely(error))
diff --git a/sql/handler.h b/sql/handler.h
index 5ef92088df5..b7b35bc2b06 100644
--- a/sql/handler.h
+++ b/sql/handler.h
@@ -1571,6 +1571,7 @@ typedef struct {
 
 #define UNDEF_NODEGROUP 65535
 class Item;
+class Exec_time_tracker;
 struct st_table_log_memory_entry;
 
 class partition_info;
@@ -2594,6 +2595,9 @@ public:
   ulonglong rows_changed;
   /* One bigger than needed to avoid to test if key == MAX_KEY */
   ulonglong index_rows_read[MAX_KEY+1];
+  
+  /* ANALYZE time tracker, if present */
+  Exec_time_tracker *tracker;
 
   Item *pushed_idx_cond;
   uint pushed_idx_cond_keyno;  /* The index which the above condition is for */
@@ -2648,6 +2652,7 @@ public:
     ft_handler(0), inited(NONE),
     implicit_emptied(0),
     pushed_cond(0), next_insert_id(0), insert_id_for_cur_row(0),
+    tracker(NULL),
     pushed_idx_cond(NULL),
     pushed_idx_cond_keyno(MAX_KEY),
     auto_inc_intervals_count(0),
diff --git a/sql/sql_analyze_stmt.h b/sql/sql_analyze_stmt.h
new file mode 100644
index 00000000000..f83ae1a57a6
--- /dev/null
+++ b/sql/sql_analyze_stmt.h
@@ -0,0 +1,50 @@
+/*
+   Copyright (c) 2015 MariaDB Corporation Ab
+
+   This program is free software; you can redistribute it and/or modify
+   it under the terms of the GNU General Public License as published by
+   the Free Software Foundation; version 2 of the License.
+
+   This program is distributed in the hope that it will be useful,
+   but WITHOUT ANY WARRANTY; without even the implied warranty of
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+   GNU General Public License for more details.
+
+   You should have received a copy of the GNU General Public License
+   along with this program; if not, write to the Free Software
+   Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
+
+
+/*
+  A class for tracking time it takes to do a certain action
+*/
+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
+  ulonglong get_loops() { return count; }
+  double get_time_ms()
+  {
+    // convert 'cycles' to milliseconds.
+    return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency;
+  }
+};
+
diff --git a/sql/sql_class.h b/sql/sql_class.h
index bd145bd4d28..75eb31755fa 100644
--- a/sql/sql_class.h
+++ b/sql/sql_class.h
@@ -5201,28 +5201,6 @@ inline int handler::ha_read_first_row(uchar *buf, uint primary_key)
   return error;
 }
 
-inline int handler::ha_write_tmp_row(uchar *buf)
-{
-  int error;
-  MYSQL_INSERT_ROW_START(table_share->db.str, table_share->table_name.str);
-  increment_statistics(&SSV::ha_tmp_write_count);
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0,
-                      { error= write_row(buf); })
-  MYSQL_INSERT_ROW_DONE(error);
-  return error;
-}
-
-inline int handler::ha_update_tmp_row(const uchar *old_data, uchar *new_data)
-{
-  int error;
-  MYSQL_UPDATE_ROW_START(table_share->db.str, table_share->table_name.str);
-  increment_statistics(&SSV::ha_tmp_update_count);
-  MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0,
-                      { error= update_row(old_data, new_data);})
-  MYSQL_UPDATE_ROW_DONE(error);
-  return error;
-}
-
 extern pthread_attr_t *get_connection_attrib(void);
 
 /**
diff --git a/sql/sql_explain.cc b/sql/sql_explain.cc
index 873ed74a1a2..9d82f4fe19f 100644
--- a/sql/sql_explain.cc
+++ b/sql/sql_explain.cc
@@ -1295,8 +1295,11 @@ void Explain_table_access::print_explain_json(Explain_query *query,
     else
       writer->add_null();
 
-    op_tracker.end_tracking();
-    op_tracker.print_json(writer);
+    if (op_tracker.get_loops())
+    {
+      writer->add_member("r_total_time_ms").
+              add_double(op_tracker.get_time_ms());
+    }
   }
   
   /* `filtered` */
@@ -1979,40 +1982,3 @@ 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 95114b197b1..50b351cf619 100644
--- a/sql/sql_explain.h
+++ b/sql/sql_explain.h
@@ -14,6 +14,7 @@
    along with this program; if not, write to the Free Software
    Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
 
+#include "sql_analyze_stmt.h"
 
 /*
 
@@ -105,7 +106,7 @@ public:
   inline void on_record_after_where() { r_rows_after_where++; }
 };
 
-
+#if 0
 /*
   A class to track operations (currently, row reads) on a PSI_table.
 */
@@ -128,7 +129,7 @@ public:
   // this may print nothing if the table was not tracked.
   void print_json(Json_writer *writer);
 };
-
+#endif
 
 #define ANALYZE_START_TRACKING(tracker) \
   if (tracker) \
@@ -138,38 +139,6 @@ public:
   if (tracker) \
   { tracker->stop_tracking(); }
 
-/*
-  A class for tracking time it takes to do a certain action
-*/
-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
-  ulonglong get_loops() { return count; }
-  double get_time_ms()
-  {
-    // convert 'cycles' to milliseconds.
-    return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency;
-  }
-};
 
 /**************************************************************************************
  
@@ -772,7 +741,7 @@ public:
 
   /* Tracker for reading the table */
   Table_access_tracker tracker;
-  Table_op_tracker op_tracker;
+  Exec_time_tracker op_tracker;
   Table_access_tracker jbuf_tracker;
 
   int print_explain(select_result_sink *output, uint8 explain_flags, 
diff --git a/sql/sql_select.cc b/sql/sql_select.cc
index 6c7e762b088..485efcc1128 100644
--- a/sql/sql_select.cc
+++ b/sql/sql_select.cc
@@ -23419,7 +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);
+  tab->table->file->tracker= &eta->op_tracker;
   /* id and select_type are kept in Explain_select */
 
   /* table */