MDEV-13330: ANALYZE FORMAT=JSON should print time spent in SPs

mysql-test/r/sp-analyze-stmt.result

+drop table if exists t0,t1;
+drop function if exists f1;
+drop function if exists f2;
+create table t0(a int);
+insert into t0 values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
+create function f1 (a int) returns int deterministic
+begin
+return a+1;
+end|
+create function f2 (a int) returns int deterministic
+begin
+return a+10;
+end|
+create function f3 (a int) returns int deterministic
+begin
+return f1(a) + f2(a);
+end|
+analyze format=json select a, f1(a),f2(a) from t0;
+ANALYZE
+{
+  "query_block": {
+    "select_id": 1,
+    "r_loops": 1,
+    "r_total_time_ms": "REPLACED",
+    "table": {
+      "table_name": "t0",
+      "access_type": "ALL",
+      "r_loops": 1,
+      "rows": 10,
+      "r_rows": 10,
+      "r_total_time_ms": "REPLACED",
+      "filtered": 100,
+      "r_filtered": 100
+    }
+  },
+  "r_stored_routines": {
+    {
+      "qname": "test.f2",
+      "r_count": 10,
+      "r_total_time_ms": "REPLACED"
+    },
+    {
+      "qname": "test.f1",
+      "r_count": 10,
+      "r_total_time_ms": "REPLACED"
+    }
+  }
+}
+analyze format=json select a, f3(a) from t0;
+ANALYZE
+{
+  "query_block": {
+    "select_id": 1,
+    "r_loops": 1,
+    "r_total_time_ms": "REPLACED",
+    "table": {
+      "table_name": "t0",
+      "access_type": "ALL",
+      "r_loops": 1,
+      "rows": 10,
+      "r_rows": 10,
+      "r_total_time_ms": "REPLACED",
+      "filtered": 100,
+      "r_filtered": 100
+    }
+  },
+  "r_stored_routines": {
+    {
+      "qname": "test.f3",
+      "r_count": 10,
+      "r_total_time_ms": "REPLACED"
+    }
+  }
+}
+analyze format=json select a, f1(a),f3(a) from t0;
+ANALYZE
+{
+  "query_block": {
+    "select_id": 1,
+    "r_loops": 1,
+    "r_total_time_ms": "REPLACED",
+    "table": {
+      "table_name": "t0",
+      "access_type": "ALL",
+      "r_loops": 1,
+      "rows": 10,
+      "r_rows": 10,
+      "r_total_time_ms": "REPLACED",
+      "filtered": 100,
+      "r_filtered": 100
+    }
+  },
+  "r_stored_routines": {
+    {
+      "qname": "test.f3",
+      "r_count": 10,
+      "r_total_time_ms": "REPLACED"
+    },
+    {
+      "qname": "test.f1",
+      "r_count": 10,
+      "r_total_time_ms": "REPLACED"
+    }
+  }
+}
+drop table t0;
+drop function f1;
+drop function f2;
+drop function f3;

mysql-test/t/sp-analyze-stmt.test

+# 
+#  MDEV-13330: Tests for the "ANALYZE command should collect SP execution time" feature
+#
+
+--disable_warnings
+drop table if exists t0,t1;
+drop function if exists f1;
+drop function if exists f2;
+--enable_warnings
+
+create table t0(a int);
+insert into t0 values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
+
+delimiter |;
+
+create function f1 (a int) returns int deterministic
+begin
+  return a+1;
+end|
+
+create function f2 (a int) returns int deterministic
+begin
+  return a+10;
+end|
+
+create function f3 (a int) returns int deterministic
+begin
+  return f1(a) + f2(a);
+end|
+
+delimiter ;|
+
+--source include/analyze-format.inc
+analyze format=json select a, f1(a),f2(a) from t0;
+
+--source include/analyze-format.inc
+analyze format=json select a, f3(a) from t0;
+
+--source include/analyze-format.inc
+analyze format=json select a, f1(a),f3(a) from t0;
+
+# TODO: tests for triggers.
+
+drop table t0;
+drop function f1;
+drop function f2;
+drop function f3;
+

sql/sp_head.cc

@@ -45,6 +45,9 @@
 #include "sql_audit.h"
 #include "debug_sync.h"
 
+#include "sql_select.h"
+#include "sql_explain.h"
+
 /*
   Sufficient max length of printed destinations and frame offsets (all uints).
 */
@@ -1145,6 +1148,13 @@ sp_head::execute(THD *thd, bool merge_da_on_success)
   if (check_stack_overrun(thd, 7 * STACK_MIN_SIZE, (uchar*)&old_packet))
     DBUG_RETURN(TRUE);
 
+  if (thd->lex->explain && thd->lex->explain->sp_tracker)
+  {
+    // TODO: how about creating sp_tracker on demand? Most queries wont need
+    // it.
+    thd->lex->explain->sp_tracker->report_routine_start(&m_qname);
+  }
+
   /* init per-instruction memroot */
   init_sql_alloc(&execute_mem_root, MEM_ROOT_BLOCK_SIZE, 0, MYF(0));
 
@@ -1452,6 +1462,13 @@ sp_head::execute(THD *thd, bool merge_da_on_success)
 
     err_status|= mysql_change_db(thd, &saved_cur_db_name, TRUE);
   }
+
+  //psergey-todo: put the second call here.
+  if (thd->lex->explain && thd->lex->explain->sp_tracker)
+  {
+    thd->lex->explain->sp_tracker->report_routine_end(&m_qname);
+  }
+
   m_flags&= ~IS_INVOKED;
   DBUG_PRINT("info",
              ("first free for 0x%lx --: 0x%lx->0x%lx, level: %lu, flags %x",

sql/sql_analyze_stmt.cc

@@ -80,3 +80,92 @@ void Filesort_tracker::print_json_members(Json_writer *writer)
   }
 }
 
+
+static 
+uchar *get_sp_call_counter_name(void *arg, 
+                                size_t *length,
+                                my_bool not_used __attribute__((unused)))
+{
+  Stored_routine_tracker::SP_call_counter *counter=
+    (Stored_routine_tracker::SP_call_counter*)arg;
+
+  *length= counter->name.length;
+  return (uchar*)counter->name.str;
+}
+
+
+extern "C" void free_stored_routine_tracker(void *arg)
+{
+  Stored_routine_tracker::SP_call_counter *counter=
+    (Stored_routine_tracker::SP_call_counter*)arg;
+  delete counter;
+}
+
+
+Stored_routine_tracker::Stored_routine_tracker()
+//: time_tracker(false) //todo remove this
+{
+  //TODO: tracker should only be used when doing timing.
+  (void)my_hash_init(&name_to_counter,
+                     system_charset_info, 10, 0, 0,
+                     (my_hash_get_key) get_sp_call_counter_name,
+                     free_stored_routine_tracker, HASH_UNIQUE);
+}
+
+
+Stored_routine_tracker::~Stored_routine_tracker()
+{
+  my_hash_free(&name_to_counter);
+}
+
+
+void Stored_routine_tracker::report_routine_start(const LEX_STRING *qname)
+{
+  SP_call_counter *cntr;
+
+  if (!(cntr= (SP_call_counter*) my_hash_search(&name_to_counter,
+                                                (const uchar*)qname->str,
+                                                qname->length)))
+  {
+    if ((cntr= new SP_call_counter))
+    {
+      cntr->name= *qname;
+      my_hash_insert(&name_to_counter, (uchar*)cntr);
+    }
+  }
+
+  if (cntr)
+    ANALYZE_START_TRACKING(&cntr->count);
+}
+
+void Stored_routine_tracker::report_routine_end(const LEX_STRING *qname)
+{
+  SP_call_counter *cntr;
+  if ((cntr= (SP_call_counter*) my_hash_search(&name_to_counter,
+                                               (const uchar*)qname->str,
+                                               qname->length)))
+  {
+    ANALYZE_STOP_TRACKING(&cntr->count);
+  }
+}
+
+void Stored_routine_tracker::print_json_members(Json_writer *writer)
+{
+  if (name_to_counter.records)
+  {
+    writer->add_member("r_stored_routines").start_object();
+    uint i;
+    for (i= 0; i < name_to_counter.records; ++i)
+    {
+      SP_call_counter *cntr= 
+        (SP_call_counter*)my_hash_element(&name_to_counter, i);
+      writer->start_object();
+      writer->add_member("qname").add_str(cntr->name.str);
+      writer->add_member("r_count").add_ll(cntr->count.get_loops());
+      writer->add_member("r_total_time_ms").add_double(cntr->count.get_time_ms());
+      writer->end_object();
+    }
+    writer->end_object();
+  }
+}
+

sql/sql_analyze_stmt.h

@@ -284,3 +284,37 @@ class Filesort_tracker : public Sql_alloc
   ulonglong sort_buffer_size;
 };
 
+
+/*
+  Tracks number of executions and total time spent in each routine invoked by
+  the statement.
+
+  Tracking happens only for routine invocations made directly by this
+  statement. 
+  For example, if the statement invokes function F1() which invokes F2(), we will not 
+  report any calls to F2. Time spent in F2() will be billed to F1().
+*/
+class Stored_routine_tracker : public Sql_alloc
+{
+  HASH name_to_counter;
+
+public:
+  class SP_call_counter
+  {
+  public:
+    SP_call_counter() : count(true) {}
+    LEX_STRING name;
+    Time_and_counter_tracker count;
+  };
+
+  Stored_routine_tracker(); //: time_tracker(do_timing) {}
+  ~Stored_routine_tracker();
+
+  /* Functions to report SP invocations */
+
+  void report_routine_start(const LEX_STRING *qname);
+  void report_routine_end(const LEX_STRING *qname);
+
+  /* Functions to get the statistics */
+  void print_json_members(Json_writer *writer);
+};

sql/sql_explain.cc

@@ -33,7 +33,8 @@ static void write_item(Json_writer *writer, Item *item);
 static void append_item_to_str(String *out, Item *item);
 
 Explain_query::Explain_query(THD *thd_arg, MEM_ROOT *root) : 
-  mem_root(root), upd_del_plan(NULL),  insert_plan(NULL),
+  mem_root(root), sp_tracker(NULL),
+  upd_del_plan(NULL),  insert_plan(NULL),
   unions(root), selects(root),  thd(thd_arg), apc_enabled(false),
   operations(0)
 {
@@ -59,6 +60,8 @@ Explain_query::~Explain_query()
 
   delete upd_del_plan;
   delete insert_plan;
+
+  delete sp_tracker;
   uint i;
   for (i= 0 ; i < unions.elements(); i++)
     delete unions.at(i);
@@ -144,6 +147,13 @@ void Explain_query::add_upd_del_plan(Explain_update *upd_del_plan_arg)
 
 void Explain_query::query_plan_ready()
 {
+  // Q: the below doesn't look stellar module-wise.
+  if (current_thd->lex->analyze_stmt)
+  {
+    // Tracking is only done when running ANALYZE.
+    sp_tracker= new Stored_routine_tracker();
+  }
+
   if (!apc_enabled)
     thd->apc_target.enable();
   apc_enabled= true;
@@ -224,6 +234,9 @@ void Explain_query::print_explain_json(select_result_sink *output,
     node->print_explain_json(this, &writer, is_analyze);
   }
 
+  if (sp_tracker)
+   sp_tracker->print_json_members(&writer);
+
   writer.end_object();
 
   CHARSET_INFO *cs= system_charset_info;

sql/sql_explain.h

@@ -468,6 +468,11 @@ class Explain_query : public Sql_alloc
   MEM_ROOT *mem_root;
 
   Explain_update *get_upd_del_plan() { return upd_del_plan; }
+  
+  /* 
+    Tracks invocations of stored routines. NULL for non-ANALYZE statements
+  */
+  Stored_routine_tracker* sp_tracker;
 private:
   /* Explain_delete inherits from Explain_update */
   Explain_update *upd_del_plan;