Make ANALYZE FORMAT=JSON show execution time for filesort element.

mysql-test/r/analyze_stmt_orderby.result

@@ -40,6 +40,7 @@ ANALYZE
     "r_total_time_ms": "REPLACED",
     "filesort": {
       "r_loops": 1,
+      "r_total_time_ms": "REPLACED",
       "r_limit": 5,
       "r_used_priority_queue": true,
       "r_output_rows": 6,
@@ -140,6 +141,7 @@ ANALYZE
     "r_total_time_ms": "REPLACED",
     "filesort": {
       "r_loops": 1,
+      "r_total_time_ms": "REPLACED",
       "r_used_priority_queue": false,
       "r_output_rows": 10000,
       "r_buffer_size": "REPLACED",
@@ -204,6 +206,7 @@ ANALYZE
     "r_total_time_ms": "REPLACED",
     "filesort": {
       "r_loops": 1,
+      "r_total_time_ms": "REPLACED",
       "r_limit": 4,
       "r_used_priority_queue": true,
       "r_output_rows": 4,
@@ -288,6 +291,7 @@ ANALYZE
       "r_rows": 10,
       "filesort": {
         "r_loops": 1,
+        "r_total_time_ms": "REPLACED",
         "r_used_priority_queue": false,
         "r_output_rows": 10,
         "r_buffer_size": "REPLACED",
@@ -343,6 +347,7 @@ ANALYZE
     "r_total_time_ms": "REPLACED",
     "filesort": {
       "r_loops": 1,
+      "r_total_time_ms": "REPLACED",
       "r_used_priority_queue": false,
       "r_output_rows": 10,
       "r_buffer_size": "REPLACED",
@@ -451,11 +456,13 @@ ANALYZE
     "r_total_time_ms": "REPLACED",
     "filesort": {
       "r_loops": 1,
+      "r_total_time_ms": "REPLACED",
       "r_limit": 1,
       "r_used_priority_queue": true,
       "r_output_rows": 2,
       "filesort": {
         "r_loops": 1,
+        "r_total_time_ms": "REPLACED",
         "r_used_priority_queue": false,
         "r_output_rows": 6,
         "r_buffer_size": "REPLACED",

sql/filesort.cc

@@ -371,7 +371,6 @@ ha_rows filesort(THD *thd, TABLE *table, SORT_FIELD *sortorder, uint s_length,
 
   err:
   my_free(param.tmp_buffer);
-  tracker->report_merge_passes_at_end(thd->query_plan_fsort_passes);
   if (!subselect || !subselect->is_uncacheable())
   {
     table_sort.free_sort_buffer();
@@ -393,6 +392,7 @@ ha_rows filesort(THD *thd, TABLE *table, SORT_FIELD *sortorder, uint s_length,
       outfile->end_of_file=save_pos;
     }
   }
+  tracker->report_merge_passes_at_end(thd->query_plan_fsort_passes);
   if (error)
   {
     int kill_errno= thd->killed_errno();

sql/sql_analyze_stmt.cc

@@ -26,29 +26,38 @@
 void Filesort_tracker::print_json_members(Json_writer *writer)
 {
   const char *varied_str= "(varied across executions)";
-  writer->add_member("r_loops").add_ll(r_loops);
+  writer->add_member("r_loops").add_ll(get_r_loops());
   
+  if (get_r_loops() && time_tracker.timed)
+  {
+    writer->add_member("r_total_time_ms").
+            add_double(time_tracker.get_time_ms());
+  }
   if (r_limit != HA_POS_ERROR)
   {
     writer->add_member("r_limit");
     if (r_limit == 0)
       writer->add_str(varied_str);
     else
-      writer->add_ll(rint(r_limit/r_loops));
+      writer->add_ll(rint(r_limit/get_r_loops()));
   }
 
   writer->add_member("r_used_priority_queue"); 
-  if (r_used_pq == r_loops)
+  if (r_used_pq == get_r_loops())
     writer->add_bool(true);
   else if (r_used_pq == 0)
     writer->add_bool(false);
   else
     writer->add_str(varied_str);
 
-  writer->add_member("r_output_rows").add_ll(rint(r_output_rows / r_loops));
+  writer->add_member("r_output_rows").add_ll(rint(r_output_rows / 
+                                                  get_r_loops()));
 
   if (sort_passes)
-    writer->add_member("r_sort_passes").add_ll(rint(sort_passes / r_loops));
+  {
+    writer->add_member("r_sort_passes").add_ll(rint(sort_passes /
+                                                    get_r_loops()));
+  }
 
   if (sort_buffer_size != 0)
   {
@@ -79,13 +88,13 @@ Filesort_tracker *Sort_and_group_tracker::report_sorting(THD *thd)
       varied_executions= true;
       cur_action++;
       if (!dummy_fsort_tracker)
-        dummy_fsort_tracker= new (thd->mem_root) Filesort_tracker();
+        dummy_fsort_tracker= new (thd->mem_root) Filesort_tracker(is_analyze);
       return dummy_fsort_tracker;
     }
     return qep_actions_data[cur_action++].filesort_tracker;
   }
 
-  Filesort_tracker *fs_tracker= new(thd->mem_root)Filesort_tracker();
+  Filesort_tracker *fs_tracker= new(thd->mem_root)Filesort_tracker(is_analyze);
   qep_actions_data[cur_action].filesort_tracker= fs_tracker;
   qep_actions[cur_action++]= EXPL_ACTION_FILESORT;
 

sql/sql_analyze_stmt.h

@@ -63,8 +63,8 @@ class Exec_time_tracker
   }
 
   // interface for getting the time
-  ulonglong get_loops() { return count; }
-  double get_time_ms()
+  ulonglong get_loops() const { return count; }
+  double get_time_ms() const
   {
     // convert 'cycles' to milliseconds.
     return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency;
@@ -169,8 +169,8 @@ class Json_writer;
 class Filesort_tracker : public Sql_alloc
 {
 public:
-  Filesort_tracker() :
-    r_loops(0), r_limit(0), r_used_pq(0), 
+  Filesort_tracker(bool do_timing) :
+    time_tracker(do_timing), r_limit(0), r_used_pq(0),
     r_examined_rows(0), r_sorted_rows(0), r_output_rows(0),
     sort_passes(0),
     sort_buffer_size(0)
@@ -180,10 +180,12 @@ class Filesort_tracker : public Sql_alloc
 
   inline void report_use(ha_rows r_limit_arg)
   {
-    if (!r_loops++)
+    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);
   }
   inline void incr_pq_used() { r_used_pq++; }
 
@@ -202,6 +204,7 @@ class Filesort_tracker : public Sql_alloc
   }
   inline void report_merge_passes_at_end(ulong passes)
   {
+    ANALYZE_STOP_TRACKING(&time_tracker);
     sort_passes += passes;
   }
 
@@ -216,14 +219,14 @@ class Filesort_tracker : public Sql_alloc
   /* Functions to get the statistics */
   void print_json_members(Json_writer *writer);
   
-  ulonglong get_r_loops() { return r_loops; }
+  ulonglong get_r_loops() const { return time_tracker.get_loops(); }
   double get_avg_examined_rows() 
   { 
-    return ((double)r_examined_rows) / r_loops;
+    return ((double)r_examined_rows) / get_r_loops();
   }
   double get_avg_returned_rows()
   { 
-    return ((double)r_output_rows) / r_loops; 
+    return ((double)r_output_rows) / get_r_loops(); 
   }
   double get_r_filtered()
   {
@@ -233,7 +236,9 @@ class Filesort_tracker : public Sql_alloc
       return 1.0;
   }
 private:
-  ulonglong r_loops; /* How many times filesort was invoked */
+  Time_and_counter_tracker time_tracker;
+
+  //ulonglong r_loops; /* How many times filesort was invoked */
   /*
     LIMIT is typically a constant. There is never "LIMIT 0".
       HA_POS_ERROR means we never had a limit
@@ -366,11 +371,12 @@ class Sort_and_group_tracker : public Sql_alloc
   qep_actions_data[MAX_QEP_ACTIONS];
   
   Filesort_tracker *dummy_fsort_tracker;
-
+  bool is_analyze;
 public:
-  Sort_and_group_tracker() : 
+  Sort_and_group_tracker(bool is_analyze_arg) :
     cur_action(0), total_actions(0), varied_executions(false),
-    dummy_fsort_tracker(NULL)
+    dummy_fsort_tracker(NULL),
+    is_analyze(is_analyze_arg)
   {}
 
   /*************** Reporting interface ***************/

sql/sql_delete.cc

@@ -159,7 +159,7 @@ void Update_plan::save_explain_data_intern(MEM_ROOT *mem_root,
   explain->where_cond= select? select->cond: NULL;
 
   if (using_filesort)
-    explain->filesort_tracker= new (mem_root) Filesort_tracker;
+    explain->filesort_tracker= new (mem_root) Filesort_tracker(is_analyze);
   explain->using_io_buffer= using_io_buffer;
 
   append_possible_keys(mem_root, explain->possible_keys, table, 

sql/sql_explain.h

@@ -210,7 +210,8 @@ class Explain_select : public Explain_basic_join
   Explain_basic_join(root),
     message(NULL),
     using_temporary(false), using_filesort(false),
-    time_tracker(is_analyze)
+    time_tracker(is_analyze),
+    ops_tracker(is_analyze)
   {}
 
   /*
@@ -729,6 +730,8 @@ class Explain_table_access : public Sql_alloc
   
   This is similar to Explain_table_access, except that it is more restrictive.
   Also, it can have UPDATE operation options, but currently there aren't any.
+
+  Explain_delete inherits from this.
 */
 
 class Explain_update : public Explain_node

sql/sql_table.cc

@@ -9374,7 +9374,7 @@ copy_data_between_tables(THD *thd, TABLE *from, TABLE *to,
       tables.db= from->s->db.str;
 
       THD_STAGE_INFO(thd, stage_sorting);
-      Filesort_tracker dummy_tracker;
+      Filesort_tracker dummy_tracker(false);
       if (thd->lex->select_lex.setup_ref_array(thd, order_num) ||
           setup_order(thd, thd->lex->select_lex.ref_pointer_array,
                       &tables, fields, all_fields, order) ||