Backport:

B-g#27060: SQL Profile utility may not be reporting right duration \
      for each step

Whenever the profiler is reset at the beginning of a query, there's
a "hidden" profiling entry that represents that point in time.  It 
has no status description, as those are set by state changes and no
such point has yet been encountered.  That profiling entry is not
in the list of entries generated when we change states.

The profiling code had the problem that each step of printing 
profiling data subtracted the previous "step"'s data, but gave the
label to that data of the current step, which is wrong.  The label/
state refers to the period beginning with that profiling data, not
ending with it.

Now, give a label to the first profiling pseudo-entry, so that we 
have a name to assign to the period that ends with the first state 
change.  Now also use the state name of the previous step in showing 
the delta values that end with this step.


sql/sql_profile.cc:
  Store a status of "initializing" whenever we construct the first
  profile entry -- the one that gets reset whenever we're starting 
  a new query, before the server sets a real status.
  
  Additionally, associate the previous status with the time period
  that ends with the current profile entry's stats.
  
  Since we need yet another piece of info from the previous profiling
  entry, take out the piecemeal ways we currently do it and make a
  general pointer to the whole thing.

1 files changed, 61 insertions, 46 deletions

diff --git a/sql/sql_profile.cc b/sql/sql_profile.cc
index 8ed3df9cd2e..4ee8d1ba9c8 100644
--- a/sql/sql_profile.cc
+++ b/sql/sql_profile.cc
@@ -72,6 +72,9 @@ PROFILE_ENTRY::PROFILE_ENTRY()
   time_usecs(0.0), allocated_status_memory(NULL)
 {
   collect();
+
+  /* The beginning of the query, before any state is set. */
+  set_status("(initialization)", NULL, NULL, 0);  
 }
 
 PROFILE_ENTRY::PROFILE_ENTRY(QUERY_PROFILE *profile_arg, const char *status_arg)
@@ -313,10 +316,7 @@ bool QUERY_PROFILE::show(uint options)
   SELECT_LEX_UNIT *unit= &thd->lex->unit;
   ha_rows idx= 0;
   unit->set_limit(sel);
-  double last_time= profile_start.time_usecs;
-#ifdef HAVE_GETRUSAGE
-  struct rusage *last_rusage= &(profile_start.rusage);
-#endif
+  PROFILE_ENTRY *previous= &profile_start;
 
   PROFILE_ENTRY *entry;
   void *iterator;
@@ -337,8 +337,18 @@ bool QUERY_PROFILE::show(uint options)
       break;
 
     protocol->prepare_for_resend();
-    protocol->store(entry->status, strlen(entry->status), system_charset_info);
-    protocol->store((double)(entry->time_usecs - last_time)/(1000.0*1000),
+
+    /*
+      This entry, n, has a point in time, T(n), and a status phrase, S(n).  The
+      status phrase S(n) describes the period of time that begins at T(n).  The
+      previous status phrase S(n-1) describes the period of time that starts at
+      T(n-1) and ends at T(n).  Since we want to describe the time that a status
+      phrase took T(n)-T(n-1), this line must describe the previous status.
+    */
+    protocol->store(previous->status, strlen(previous->status), 
+                    system_charset_info);
+    protocol->store((double)(entry->time_usecs - 
+                    previous->time_usecs)/(1000.0*1000),
                     (uint32) TIME_FLOAT_DIGITS-1, &elapsed);
 
     if (options & PROFILE_CPU)
@@ -346,10 +356,10 @@ bool QUERY_PROFILE::show(uint options)
 #ifdef HAVE_GETRUSAGE
       String cpu_utime, cpu_stime;
       protocol->store((double)(RUSAGE_DIFF_USEC(rusage->ru_utime,
-                      last_rusage->ru_utime))/(1000.0*1000),
+                      previous->rusage.ru_utime))/(1000.0*1000),
                       (uint32) TIME_FLOAT_DIGITS-1, &cpu_utime);
       protocol->store((double)(RUSAGE_DIFF_USEC(rusage->ru_stime,
-                      last_rusage->ru_stime))/(1000.0*1000),
+                      previous->rusage.ru_stime))/(1000.0*1000),
                       (uint32) TIME_FLOAT_DIGITS-1, &cpu_stime);
 #else
       protocol->store_null();
@@ -360,8 +370,8 @@ bool QUERY_PROFILE::show(uint options)
     if (options & PROFILE_CONTEXT)
     {
 #ifdef HAVE_GETRUSAGE
-      protocol->store((uint32)(rusage->ru_nvcsw - last_rusage->ru_nvcsw));
-      protocol->store((uint32)(rusage->ru_nivcsw - last_rusage->ru_nivcsw));
+      protocol->store((uint32)(rusage->ru_nvcsw - previous->rusage.ru_nvcsw));
+      protocol->store((uint32)(rusage->ru_nivcsw - previous->rusage.ru_nivcsw));
 #else
       protocol->store_null();
       protocol->store_null();
@@ -371,8 +381,8 @@ bool QUERY_PROFILE::show(uint options)
     if (options & PROFILE_BLOCK_IO)
     {
 #ifdef HAVE_GETRUSAGE
-      protocol->store((uint32)(rusage->ru_inblock - last_rusage->ru_inblock));
-      protocol->store((uint32)(rusage->ru_oublock - last_rusage->ru_oublock));
+      protocol->store((uint32)(rusage->ru_inblock - previous->rusage.ru_inblock));
+      protocol->store((uint32)(rusage->ru_oublock - previous->rusage.ru_oublock));
 #else
       protocol->store_null();
       protocol->store_null();
@@ -382,8 +392,8 @@ bool QUERY_PROFILE::show(uint options)
     if (options & PROFILE_IPC)
     {
 #ifdef HAVE_GETRUSAGE
-      protocol->store((uint32)(rusage->ru_msgsnd - last_rusage->ru_msgsnd));
-      protocol->store((uint32)(rusage->ru_msgrcv - last_rusage->ru_msgrcv));
+      protocol->store((uint32)(rusage->ru_msgsnd - previous->rusage.ru_msgsnd));
+      protocol->store((uint32)(rusage->ru_msgrcv - previous->rusage.ru_msgrcv));
 #else
       protocol->store_null();
       protocol->store_null();
@@ -393,8 +403,8 @@ bool QUERY_PROFILE::show(uint options)
     if (options & PROFILE_PAGE_FAULTS)
     {
 #ifdef HAVE_GETRUSAGE
-      protocol->store((uint32)(rusage->ru_majflt - last_rusage->ru_majflt));
-      protocol->store((uint32)(rusage->ru_minflt - last_rusage->ru_minflt));
+      protocol->store((uint32)(rusage->ru_majflt - previous->rusage.ru_majflt));
+      protocol->store((uint32)(rusage->ru_minflt - previous->rusage.ru_minflt));
 #else
       protocol->store_null();
       protocol->store_null();
@@ -404,7 +414,7 @@ bool QUERY_PROFILE::show(uint options)
     if (options & PROFILE_SWAPS)
     {
 #ifdef HAVE_GETRUSAGE
-      protocol->store((uint32)(rusage->ru_nswap - last_rusage->ru_nswap));
+      protocol->store((uint32)(rusage->ru_nswap - previous->rusage.ru_nswap));
 #else
       protocol->store_null();
 #endif
@@ -428,11 +438,7 @@ bool QUERY_PROFILE::show(uint options)
     if (protocol->write())
       DBUG_RETURN(TRUE);
 
-    last_time= entry->time_usecs;
-#ifdef HAVE_GETRUSAGE
-    last_rusage= &(entry->rusage);
-#endif
-
+    previous= entry;
   }
   send_eof(thd);
   DBUG_RETURN(FALSE);
@@ -648,12 +654,7 @@ int PROFILING::fill_statistics_info(THD *thd, struct st_table_list *tables, Item
        history_iterator= history.iterator_next(history_iterator))
   {
     query= history.iterator_value(history_iterator);
-
-    PROFILE_ENTRY *ps= &(query->profile_start);
-    double last_time= ps->time_usecs;
-#ifdef HAVE_GETRUSAGE
-    struct rusage *last_rusage= &(ps->rusage);
-#endif
+    PROFILE_ENTRY *previous= &(query->profile_start);
 
     /*
       Because we put all profiling info into a table that may be reordered, let
@@ -668,14 +669,10 @@ int PROFILING::fill_statistics_info(THD *thd, struct st_table_list *tables, Item
     for (seq= 0, entry_iterator= query->entries.new_iterator(); 
          entry_iterator != NULL; 
          entry_iterator= query->entries.iterator_next(entry_iterator),
-#ifdef HAVE_GETRUSAGE
-         last_rusage= &(entry->rusage),
-#endif
-         seq++, last_time= entry->time_usecs, row_number++)
+         seq++, previous=entry, row_number++)
     {
       entry= query->entries.iterator_value(entry_iterator);
 
-
       /* Set default values for this row. */
       restore_record(table, s->default_values);
 
@@ -685,16 +682,25 @@ int PROFILING::fill_statistics_info(THD *thd, struct st_table_list *tables, Item
       */
       table->field[0]->store((ulonglong) query->profiling_query_id);
       table->field[1]->store((ulonglong) seq); /* the step in the sequence */
-      table->field[2]->store(entry->status, strlen(entry->status), 
+      /*
+        This entry, n, has a point in time, T(n), and a status phrase, S(n).
+        The status phrase S(n) describes the period of time that begins at
+        T(n).  The previous status phrase S(n-1) describes the period of time
+        that starts at T(n-1) and ends at T(n).  Since we want to describe the
+        time that a status phrase took T(n)-T(n-1), this line must describe the
+        previous status.
+      */
+      table->field[2]->store(previous->status, strlen(previous->status), 
                              system_charset_info);
-      table->field[3]->store((double)(entry->time_usecs - last_time)/(1000*1000));
+      table->field[3]->store((double)(entry->time_usecs - 
+                             previous->time_usecs)/(1000*1000));
 
 #ifdef HAVE_GETRUSAGE
       table->field[4]->store((double)RUSAGE_DIFF_USEC(entry->rusage.ru_utime,
-                             last_rusage->ru_utime)/(1000.0*1000));
+                             previous->rusage.ru_utime)/(1000.0*1000));
       table->field[4]->set_notnull();
       table->field[5]->store((double)RUSAGE_DIFF_USEC(entry->rusage.ru_stime,
-                             last_rusage->ru_stime)/(1000.0*1000));
+                             previous->rusage.ru_stime)/(1000.0*1000));
 
       table->field[5]->set_notnull();
 #else
@@ -702,43 +708,52 @@ int PROFILING::fill_statistics_info(THD *thd, struct st_table_list *tables, Item
 #endif
       
 #ifdef HAVE_GETRUSAGE
-      table->field[6]->store((uint32)(entry->rusage.ru_nvcsw - last_rusage->ru_nvcsw));
+      table->field[6]->store((uint32)(entry->rusage.ru_nvcsw - 
+                             previous->rusage.ru_nvcsw));
       table->field[6]->set_notnull();
-      table->field[7]->store((uint32)(entry->rusage.ru_nivcsw - last_rusage->ru_nivcsw));
+      table->field[7]->store((uint32)(entry->rusage.ru_nivcsw - 
+                             previous->rusage.ru_nivcsw));
       table->field[7]->set_notnull();
 #else
       /* TODO: Add context switch info for non-BSD systems */
 #endif
 
 #ifdef HAVE_GETRUSAGE
-      table->field[8]->store((uint32)(entry->rusage.ru_inblock - last_rusage->ru_inblock));
+      table->field[8]->store((uint32)(entry->rusage.ru_inblock - 
+                             previous->rusage.ru_inblock));
       table->field[8]->set_notnull();
-      table->field[9]->store((uint32)(entry->rusage.ru_oublock - last_rusage->ru_oublock));
+      table->field[9]->store((uint32)(entry->rusage.ru_oublock - 
+                             previous->rusage.ru_oublock));
       table->field[9]->set_notnull();
 #else
       /* TODO: Add block IO info for non-BSD systems */
 #endif
     
 #ifdef HAVE_GETRUSAGE
-      table->field[10]->store((uint32)(entry->rusage.ru_msgsnd - last_rusage->ru_msgsnd), true);
+      table->field[10]->store((uint32)(entry->rusage.ru_msgsnd - 
+                             previous->rusage.ru_msgsnd), true);
       table->field[10]->set_notnull();
-      table->field[11]->store((uint32)(entry->rusage.ru_msgrcv - last_rusage->ru_msgrcv), true);
+      table->field[11]->store((uint32)(entry->rusage.ru_msgrcv - 
+                             previous->rusage.ru_msgrcv), true);
       table->field[11]->set_notnull();
 #else
       /* TODO: Add message info for non-BSD systems */
 #endif
     
 #ifdef HAVE_GETRUSAGE
-      table->field[12]->store((uint32)(entry->rusage.ru_majflt - last_rusage->ru_majflt), true);
+      table->field[12]->store((uint32)(entry->rusage.ru_majflt - 
+                             previous->rusage.ru_majflt), true);
       table->field[12]->set_notnull();
-      table->field[13]->store((uint32)(entry->rusage.ru_minflt - last_rusage->ru_minflt), true);
+      table->field[13]->store((uint32)(entry->rusage.ru_minflt - 
+                             previous->rusage.ru_minflt), true);
       table->field[13]->set_notnull();
 #else
       /* TODO: Add page fault info for non-BSD systems */
 #endif
 
 #ifdef HAVE_GETRUSAGE
-      table->field[14]->store((uint32)(entry->rusage.ru_nswap - last_rusage->ru_nswap), true);
+      table->field[14]->store((uint32)(entry->rusage.ru_nswap - 
+                             previous->rusage.ru_nswap), true);
       table->field[14]->set_notnull();
 #else
       /* TODO: Add swap info for non-BSD systems */