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

- Initial implementation.

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)

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
 

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)
 {

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;

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

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:

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;
 }
 

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.

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));