MDEV-407: Print EXPLAIN [ANALYZE] in the slow query log

- Initial implementation. 

9 files changed, 136 insertions, 3 deletions

diff --git a/sql/log.cc b/sql/log.cc
index 041a0b555d1..5d8b650b494 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -2825,6 +2825,15 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
                       "Yes" : "No"),
                      thd->query_plan_fsort_passes) == (size_t) -1)
        tmp_errno= errno;
+    if (thd->variables.log_slow_verbosity & LOG_SLOW_VERBOSITY_EXPLAIN &&
+        thd->lex->query_plan_footprint)
+    {
+      StringBuffer<128> buf;
+      DBUG_ASSERT(!thd->free_list);
+      print_qpf_query(thd->lex, thd, &buf);
+      my_b_printf(&log_file, "%s", buf.c_ptr_safe());
+      thd->free_items();
+    }
     if (thd->db && strcmp(thd->db, db))
     {						// Database changed
       if (my_b_printf(&log_file,"use %s;\n",thd->db) == (size_t) -1)
diff --git a/sql/log_slow.h b/sql/log_slow.h
index 92a2d1bf4f6..e8faf79a047 100644
--- a/sql/log_slow.h
+++ b/sql/log_slow.h
@@ -18,6 +18,7 @@
 #define LOG_SLOW_VERBOSITY_INIT           0
 #define LOG_SLOW_VERBOSITY_INNODB         1 << 0
 #define LOG_SLOW_VERBOSITY_QUERY_PLAN     1 << 1
+#define LOG_SLOW_VERBOSITY_EXPLAIN        1 << 2
 
 #define QPLAN_INIT            QPLAN_QC_NO
 
diff --git a/sql/opt_qpf.cc b/sql/opt_qpf.cc
index f594d2b1b22..fc2597bcd73 100644
--- a/sql/opt_qpf.cc
+++ b/sql/opt_qpf.cc
@@ -120,6 +120,23 @@ int QPF_query::print_explain(select_result_sink *output,
   }
 }
 
+void print_qpf_query(LEX *lex, THD *thd, String *str)
+{
+  lex->query_plan_footprint->print_explain_str(thd, str);
+}
+
+bool QPF_query::print_explain_str(THD *thd, String *out_str)
+{
+  List<Item> fields;
+  thd->make_explain_field_list(fields);
+
+  select_result_text_buffer output_buf(thd);
+  output_buf.send_result_set_metadata(fields, thd->lex->describe);
+  print_explain(&output_buf, 0);
+  output_buf.save_to(out_str);
+  return false;
+}
+
 
 static void push_str(List<Item> *item_list, const char *str)
 {
diff --git a/sql/opt_qpf.h b/sql/opt_qpf.h
index b3996fcb58d..e59af85a988 100644
--- a/sql/opt_qpf.h
+++ b/sql/opt_qpf.h
@@ -230,6 +230,9 @@ public:
   /* Produce a tabular EXPLAIN output */
   int print_explain(select_result_sink *output, uint8 explain_flags);
   
+  /* Return tabular EXPLAIN output as a text string */
+  bool print_explain_str(THD *thd, String *out_str);
+
   /* If true, at least part of EXPLAIN can be printed */
   bool have_query_plan() { return upd_del_plan!= NULL || get_node(1) != NULL; }
   MEM_ROOT *mem_root;
diff --git a/sql/sql_class.h b/sql/sql_class.h
index 81b5f2847d3..ba14af850be 100644
--- a/sql/sql_class.h
+++ b/sql/sql_class.h
@@ -3442,6 +3442,26 @@ public:
 };
 
 
+/*
+  This is a select_result_sink which stores the data in text form.
+*/
+
+class select_result_text_buffer : public select_result_sink
+{
+public:
+  select_result_text_buffer(THD *thd_arg) : thd(thd_arg) {}
+  int send_data(List<Item> &items);
+  bool send_result_set_metadata(List<Item> &fields, uint flag);
+
+  void save_to(String *res);
+private:
+  int append_row(List<Item> &items, bool send_names);
+
+  THD *thd;
+  List<char*> rows;
+  int n_columns;
+};
+
 
 /*
   Base class for select_result descendands which intercept and
diff --git a/sql/sql_lex.h b/sql/sql_lex.h
index d06f31bd53f..77f0054d122 100644
--- a/sql/sql_lex.h
+++ b/sql/sql_lex.h
@@ -622,6 +622,7 @@ class QPF_query;
 
 void delete_qpf_query(LEX *lex);
 void create_qpf_query(LEX *lex, MEM_ROOT *mem_root);
+void print_qpf_query(LEX *lex, THD *thd, String *str);
 
 class st_select_lex_unit: public st_select_lex_node {
 protected:
diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc
index 011fc3e9347..b8ab4cef1be 100644
--- a/sql/sql_parse.cc
+++ b/sql/sql_parse.cc
@@ -1529,7 +1529,6 @@ void log_slow_statement(THD *thd)
 {
   DBUG_ENTER("log_slow_statement");
 
-  delete_qpf_query(thd->lex);
 
   /*
     The following should never be true with our current code base,
@@ -1567,6 +1566,8 @@ void log_slow_statement(THD *thd)
                    thd->utime_after_query);
     thd_proc_info(thd, 0);
   }
+
+  delete_qpf_query(thd->lex);
   DBUG_VOID_RETURN;
 }
 
diff --git a/sql/sql_show.cc b/sql/sql_show.cc
index d5a65a9640e..c463be985c4 100644
--- a/sql/sql_show.cc
+++ b/sql/sql_show.cc
@@ -2377,6 +2377,86 @@ int select_result_explain_buffer::send_data(List<Item> &items)
   DBUG_RETURN(test(res));
 }
 
+bool select_result_text_buffer::send_result_set_metadata(List<Item> &fields, uint flag)
+{
+  n_columns= fields.elements;
+  return append_row(fields, true /*send item names */);
+  return send_data(fields);
+}
+
+
+int select_result_text_buffer::send_data(List<Item> &items)
+{
+  return append_row(items, false /*send item values */);
+}
+
+int select_result_text_buffer::append_row(List<Item> &items, bool send_names)
+{
+  List_iterator<Item> it(items);
+  Item *item;
+  char **row;
+  int column= 0;
+
+  if (!(row= (char**) thd->alloc(sizeof(char*) * n_columns)))
+    return true;
+  rows.push_back(row);
+
+  while ((item= it++))
+  {
+    DBUG_ASSERT(column < n_columns);
+    StringBuffer<32> buf;
+    const char *data_ptr; 
+    size_t data_len;
+    if (send_names)
+    {
+      data_ptr= item->name;
+      data_len= strlen(item->name);
+    }
+    else
+    {
+      String *res;
+      res= item->val_str(&buf);
+      if (item->null_value)
+      {
+        data_ptr= "NULL";
+        data_len=4;
+      }
+      else
+      {
+        data_ptr= res->c_ptr_safe();
+        data_len= res->length();
+      }
+    }
+
+    char *ptr= (char*)thd->alloc(data_len + 1);
+    memcpy(ptr, data_ptr, data_len + 1);
+    row[column]= ptr;
+
+    column++;
+  }
+  return false;
+}
+
+
+void select_result_text_buffer::save_to(String *res)
+{
+  List_iterator<char*> it(rows);
+  char **row;
+  res->append("#\n");
+  while ((row= it++))
+  {
+    res->append("#  ");
+    for (int i=0; i < n_columns; i++)
+    {
+      if (i)
+        res->append('\t');
+      res->append(row[i]);
+    }
+    res->append("\n");
+  }
+  res->append("#\n");
+}
+
 
 /*
   Store the SHOW EXPLAIN output in the temporary table.
diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc
index 3827e3f4b67..80b7f25324d 100644
--- a/sql/sys_vars.cc
+++ b/sql/sys_vars.cc
@@ -4115,11 +4115,12 @@ static Sys_var_ulong Sys_log_slow_rate_limit(
        SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
        VALID_RANGE(1, UINT_MAX), DEFAULT(1), BLOCK_SIZE(1));
 
-static const char *log_slow_verbosity_names[]= { "innodb", "query_plan", 0 };
+static const char *log_slow_verbosity_names[]= { "innodb", "query_plan", 
+                                                 "explain", 0 };
 static Sys_var_set Sys_log_slow_verbosity(
        "log_slow_verbosity",
        "log-slow-verbosity=[value[,value ...]] where value is one of "
-       "'innodb', 'query_plan'",
+       "'innodb', 'query_plan', 'explain' ",
        SESSION_VAR(log_slow_verbosity), CMD_LINE(REQUIRED_ARG),
        log_slow_verbosity_names, DEFAULT(LOG_SLOW_VERBOSITY_INIT));