bk commit into 5.0 tree (cmiller:1.2421) BUG#27060

[Chad MILLER]

Below is the list of changes that have just been committed into a local
5.0 repository of cmiller. When cmiller does a push these changes will
be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html

ChangeSet@stripped, 2007-03-14 20:20:42-04:00, cmiller@stripped +1 -0
  Bug#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@stripped, 2007-03-14 20:20:40-04:00, cmiller@stripped +61 -44
    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.

# This is a BitKeeper patch.  What follows are the unified diffs for the
# set of deltas contained in the patch.  The rest of the patch, the part
# that BitKeeper cares about, is below these diffs.
# User:	cmiller
# Host:	zippy.cornsilk.net
# Root:	/home/cmiller/work/mysql/mysql-5.0-comeng--bug27060

--- 1.4/sql/sql_profile.cc	2007-03-14 20:20:46 -04:00
+++ 1.5/sql/sql_profile.cc	2007-03-14 20:20:46 -04:00
@@ -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)
@@ -339,10 +342,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;
 
   List_iterator<PROFILE_ENTRY> it(entries);
   PROFILE_ENTRY *entry;
@@ -359,8 +359,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)
@@ -368,10 +378,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();
@@ -382,8 +392,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();
@@ -393,8 +403,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();
@@ -404,8 +414,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();
@@ -415,8 +425,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();
@@ -426,7 +436,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
@@ -450,11 +460,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);
@@ -686,11 +692,7 @@ int PROFILING::fill_statistics_info(THD 
   /* Go through each query in this thread's stored history... */
   while ((query= query_it++) != NULL)
   {
-    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
@@ -704,10 +706,7 @@ int PROFILING::fill_statistics_info(THD 
     /* ...and for each query, go through all its state-change steps. */
     for (seq= 0, entry= step_it++; 
          entry != NULL; 
-#ifdef HAVE_GETRUSAGE
-         last_rusage= &(entry->rusage),
-#endif
-         seq++, last_time= entry->time_usecs, entry= step_it++, row_number++)
+         seq++, previous= entry, entry= step_it++, row_number++)
     {
       /* Set default values for this row. */
       restore_record(table, s->default_values);
@@ -718,16 +717,25 @@ int PROFILING::fill_statistics_info(THD 
       */
       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
@@ -735,43 +743,52 @@ int PROFILING::fill_statistics_info(THD 
 #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 */