Rewrite profiler code to be easier to maintain and less buggy.

Between 5.0 and 5.1, the step of incrementing the global query id
changed, which broke how the profiler noticed when a new query had
started.  That reset the state list and caused all but the last 
five (or so) states to be thrown away.

Now, don't watch for query_id changes in the lower level.

Add a bogus state change at the end of profiling so that the last 
real state change is timed.

Emit source reference for the start of the span of time instead of
the end of it.


mysql-test/r/profiling.result:
  Add a test that shows continuation of execution with multi-statement
  packets.
mysql-test/t/profiling.test:
  Add a test that shows continuation of execution with multi-statement
  packets.
sql/sql_parse.cc:
  Insert profiling calls at beginnings and ends of each query.
  
  Remove the old way of keeping or discarding profiles, and flipping 
  to new query profiles.
sql/sql_profile.cc:
  No longer use the thread's query_id to determine when we flip
  to a new statement.
  
  Some status statements are set to be NULL in the server.  We don't
  log those, as it doesn't fit this style of profiling yet.
  
  Rewrite the parser code to be more active and legible.  
  
  Relying on passive/lazy discovery of new queries was buggy.
  
  Add a bogus status change before ending a profile, so that the 
  previous real status has a endpoint.
  
  Emit source reference of the start of the span-of-time instead of
  the end of it.
sql/sql_profile.h:
  Store the server_query_id at instantiation time for a new query.
  
  Rewrite the parser code to be more active.  Relying on passive/lazy
  discovery of new queries was buggy.
  
  Name first state to more honestly describe the state.  We don't 
  really know of initialization that will follow.
sql/sql_show.cc:
  Update comment to note the decidedly weird field_length behavior
  on Decimal types in information_schema.

mysql-test/r/profiling.result

@@ -364,5 +364,17 @@ drop view if exists v1;
 Warnings:
 Note	1051	Unknown table 'test.v1'
 drop function if exists f1;
+select 1; select 2; select 3;;
+1
+1
+2
+2
+3
+3
+select state from information_schema.profiling where seq=1 order by query_id desc limit 3;
+state
+continuing
+continuing
+initializing
 set session profiling = OFF;
 End of 5.0 tests

mysql-test/t/profiling.test

@@ -195,6 +195,11 @@ drop table if exists t1, t2, t3;
 drop view if exists v1;
 drop function if exists f1;
 
+# Multiple queries in one packet.
+--eval select 1; select 2; select 3;
+# two continuations, one initialization
+select state from information_schema.profiling where seq=1 order by query_id desc limit 3;
+
 ## last thing in the file
 set session profiling = OFF;
 

sql/sql_parse.cc

@@ -426,6 +426,10 @@ pthread_handler_t handle_bootstrap(void *arg)
                                           QUERY_CACHE_FLAGS_SIZE);
     thd->query[length] = '\0';
     DBUG_PRINT("query",("%-.4096s",thd->query));
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+    thd->profiling.set_query_source(thd->query, length);
+#endif
+
     /*
       We don't need to obtain LOCK_thread_count here because in bootstrap
       mode we have only one thread.
@@ -645,6 +649,9 @@ int end_trans(THD *thd, enum enum_mysql_completiontype completion)
 /*
   Read one command from connection and execute it (query or simple command).
   This function is called in loop from thread function.
+
+  For profiling to work, it must never be called recursively.
+
   SYNOPSIS
     do_command()
   RETURN VALUE
@@ -654,12 +661,16 @@ int end_trans(THD *thd, enum enum_mysql_completiontype completion)
 
 bool do_command(THD *thd)
 {
+  bool return_value;
   char *packet= 0;
   ulong packet_length;
   NET *net= &thd->net;
   enum enum_server_command command;
   DBUG_ENTER("do_command");
 
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+  thd->profiling.start_new_query();
+#endif
   /*
     indicator of uninitialized lex => normal flow of errors handling
     (see my_message_sql)
@@ -686,11 +697,15 @@ bool do_command(THD *thd)
     /* Check if we can continue without closing the connection */
 
     if (net->error != 3)
-      DBUG_RETURN(TRUE);			// We have to close it.
+    {
+      return_value= TRUE;			// We have to close it.
+      goto out;
+    }
 
     net_send_error(thd, net->last_errno, NullS);
     net->error= 0;
-    DBUG_RETURN(FALSE);
+    return_value= FALSE;
+    goto out;
   }
 
   packet= (char*) net->read_pos;
@@ -724,7 +739,13 @@ bool do_command(THD *thd)
   my_net_set_read_timeout(net, thd->variables.net_read_timeout);
 
   DBUG_ASSERT(packet_length);
-  DBUG_RETURN(dispatch_command(command, thd, packet+1, (uint) (packet_length-1)));
+  return_value= dispatch_command(command, thd, packet+1, (uint) (packet_length-1));
+
+out:
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+  thd->profiling.finish_current_query();
+#endif
+  DBUG_RETURN(return_value);
 }
 #endif  /* EMBEDDED_LIBRARY */
 
@@ -982,19 +1003,22 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
       break;					// fatal error is set
     char *packet_end= thd->query + thd->query_length;
     /* 'b' stands for 'buffer' parameter', special for 'my_snprintf' */
-    const char* found_semicolon= NULL;
+    const char* end_of_stmt= NULL;
 
     general_log_write(thd, command, thd->query, thd->query_length);
     DBUG_PRINT("query",("%-.4096s",thd->query));
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+    thd->profiling.set_query_source(thd->query, thd->query_length);
+#endif
 
     if (!(specialflag & SPECIAL_NO_PRIOR))
       my_pthread_setprio(pthread_self(),QUERY_PRIOR);
 
-    mysql_parse(thd, thd->query, thd->query_length, & found_semicolon);
+    mysql_parse(thd, thd->query, thd->query_length, &end_of_stmt);
 
-    while (!thd->killed && found_semicolon && !thd->net.report_error)
+    while (!thd->killed && (end_of_stmt != NULL) && !thd->net.report_error)
     {
-      char *next_packet= (char*) found_semicolon;
+      char *beginning_of_next_stmt= (char*) end_of_stmt;
       net->no_send_error= 0;
       /*
         Multiple queries exits, execute them individually
@@ -1002,24 +1026,31 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
       if (thd->lock || thd->open_tables || thd->derived_tables ||
           thd->prelocked_mode)
         close_thread_tables(thd);
-      ulong length= (ulong)(packet_end - next_packet);
+      ulong length= (ulong)(packet_end - beginning_of_next_stmt);
 
       log_slow_statement(thd);
 
       /* Remove garbage at start of query */
-      while (my_isspace(thd->charset(), *next_packet) && length > 0)
+      while (length > 0 && my_isspace(thd->charset(), *beginning_of_next_stmt))
       {
-        next_packet++;
+        beginning_of_next_stmt++;
         length--;
       }
+
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+      thd->profiling.finish_current_query();
+      thd->profiling.start_new_query("continuing");
+      thd->profiling.set_query_source(beginning_of_next_stmt, length);
+#endif
+
       VOID(pthread_mutex_lock(&LOCK_thread_count));
       thd->query_length= length;
-      thd->query= next_packet;
+      thd->query= beginning_of_next_stmt;
       thd->query_id= next_query_id();
       thd->set_time(); /* Reset the query start time. */
       /* TODO: set thd->lex->sql_command to SQLCOM_END here */
       VOID(pthread_mutex_unlock(&LOCK_thread_count));
-      mysql_parse(thd, next_packet, length, & found_semicolon);
+      mysql_parse(thd, beginning_of_next_stmt, length, &end_of_stmt);
     }
 
     if (!(specialflag & SPECIAL_NO_PRIOR))
@@ -1516,8 +1547,8 @@ int prepare_schema_table(THD *thd, LEX *lex, Table_ident *table_ident,
       Mark this current profiling record to be discarded.  We don't
       wish to have SHOW commands show up in profiling.
     */
-#ifdef ENABLED_PROFILING
-    thd->profiling.discard();
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+    thd->profiling.discard_current_query();
 #endif
     break;
   case SCH_OPEN_TABLES:
@@ -2012,8 +2043,7 @@ mysql_execute_command(THD *thd)
   case SQLCOM_SHOW_PROFILES:
   {
 #if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
-    thd->profiling.store();
-    thd->profiling.discard();
+    thd->profiling.discard_current_query();
     res= thd->profiling.show_profiles();
     if (res)
       goto error;
@@ -5274,9 +5304,6 @@ void mysql_reset_thd_for_next_command(THD *thd)
     thd->total_warn_count=0;			// Warnings for this query
     thd->rand_used= 0;
     thd->sent_row_count= thd->examined_row_count= 0;
-#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
-    thd->profiling.reset();
-#endif
   }
   /*
     Because we come here only for start of top-statements, binlog format is

sql/sql_profile.cc

@@ -14,14 +14,28 @@
    Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
 
 
+/**
+  @file
+
+  Implement query profiling as as list of metaphorical fences, with one fence
+  per query, and each fencepost a change of thd->proc_info state (with a
+  snapshot of system statistics).  When asked, we can then iterate over the 
+  fenceposts and calculate the distance between them, to inform the user what
+  happened during a particular query or thd->proc_info state.
+
+  User variables that inform profiling behavior:
+  - "profiling", boolean, session only, "Are queries profiled?"
+  - "profiling_history_size", integer, session + global, "Num queries stored?"
+*/
+
+
 #include "mysql_priv.h"
 #include "my_sys.h"
 
 #define TIME_FLOAT_DIGITS 9
+#define TIME_I_S_DECIMAL_SIZE (6*100)+6 /**< two vals encoded: (dec*100)+len */
 #define MAX_QUERY_LENGTH 300
 
-bool schema_table_store_record(THD *thd, TABLE *table);
-
 /* Reserved for systems that can't record the function name in source. */
 const char * const _unknown_func_ = "<unknown>";
 
@@ -45,9 +59,9 @@ ST_FIELD_INFO query_profile_statistics_info[]=
   {"QUERY_ID", 20, MYSQL_TYPE_LONG, 0, false, "Query_id", SKIP_OPEN_TABLE},
   {"SEQ", 20, MYSQL_TYPE_LONG, 0, false, "Seq", SKIP_OPEN_TABLE},
   {"STATE", 30, MYSQL_TYPE_STRING, 0, false, "Status", SKIP_OPEN_TABLE},
-  {"DURATION", TIME_FLOAT_DIGITS, MYSQL_TYPE_DOUBLE, 0, false, "Duration", SKIP_OPEN_TABLE},
-  {"CPU_USER", TIME_FLOAT_DIGITS, MYSQL_TYPE_DOUBLE, 0, true, "CPU_user", SKIP_OPEN_TABLE},
-  {"CPU_SYSTEM", TIME_FLOAT_DIGITS, MYSQL_TYPE_DOUBLE, 0, true, "CPU_system", SKIP_OPEN_TABLE},
+  {"DURATION", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, false, "Duration", SKIP_OPEN_TABLE},
+  {"CPU_USER", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, true, "CPU_user", SKIP_OPEN_TABLE},
+  {"CPU_SYSTEM", TIME_I_S_DECIMAL_SIZE, MYSQL_TYPE_DECIMAL, 0, true, "CPU_system", SKIP_OPEN_TABLE},
   {"CONTEXT_VOLUNTARY", 20, MYSQL_TYPE_LONG, 0, true, "Context_voluntary", SKIP_OPEN_TABLE},
   {"CONTEXT_INVOLUNTARY", 20, MYSQL_TYPE_LONG, 0, true, "Context_involuntary", SKIP_OPEN_TABLE},
   {"BLOCK_OPS_IN", 20, MYSQL_TYPE_LONG, 0, true, "Block_ops_in", SKIP_OPEN_TABLE},
@@ -60,7 +74,7 @@ ST_FIELD_INFO query_profile_statistics_info[]=
   {"SOURCE_FUNCTION", 30, MYSQL_TYPE_STRING, 0, true, "Source_function", SKIP_OPEN_TABLE},
   {"SOURCE_FILE", 20, MYSQL_TYPE_STRING, 0, true, "Source_file", SKIP_OPEN_TABLE},
   {"SOURCE_LINE", 20, MYSQL_TYPE_LONG, 0, true, "Source_line", SKIP_OPEN_TABLE},
-  {NULL, 0, MYSQL_TYPE_STRING, 0, true, NULL, NULL}
+  {NULL, 0,  MYSQL_TYPE_STRING, 0, true, NULL, 0}
 };
 
 
@@ -118,40 +132,36 @@ int make_profile_table_for_show(THD *thd, ST_SCHEMA_TABLE *schema_table)
 #define RUSAGE_USEC(tv)  ((tv).tv_sec*1000*1000 + (tv).tv_usec)
 #define RUSAGE_DIFF_USEC(tv1, tv2) (RUSAGE_USEC((tv1))-RUSAGE_USEC((tv2)))
 
-PROFILE_ENTRY::PROFILE_ENTRY()
-  :profile(NULL), status(NULL), function(NULL), file(NULL), line(0), 
-  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)
+PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char
+                                   *status_arg)
   :profile(profile_arg)
 {
   collect();
-  set_status(status_arg, NULL, NULL, 0);
+  set_label(status_arg, NULL, NULL, 0);
 }
 
-PROFILE_ENTRY::PROFILE_ENTRY(QUERY_PROFILE *profile_arg, const char *status_arg,
+PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, 
+                                   const char *status_arg, 
                                    const char *function_arg, 
-                             const char *file_arg, unsigned int line_arg)
+                                   const char *file_arg,
+                                   unsigned int line_arg)
   :profile(profile_arg)
 {
   collect();
-  set_status(status_arg, function_arg, file_arg, line_arg);
+  set_label(status_arg, function_arg, file_arg, line_arg);
 }
 
-PROFILE_ENTRY::~PROFILE_ENTRY()
+PROF_MEASUREMENT::~PROF_MEASUREMENT()
 {
   if (allocated_status_memory != NULL)
     my_free(allocated_status_memory, MYF(0));
   status= function= file= NULL;
 }
 
-void PROFILE_ENTRY::set_status(const char *status_arg, const char *function_arg, const char *file_arg, unsigned int line_arg)
+void PROF_MEASUREMENT::set_label(const char *status_arg, 
+                                 const char *function_arg,
+                                 const char *file_arg, unsigned int line_arg)
 {
   size_t sizes[3];                              /* 3 == status+function+file */
   char *cursor;
@@ -199,7 +209,15 @@ void PROFILE_ENTRY::set_status(const char *status_arg, const char *function_arg,
   line= line_arg;
 }
 
-void PROFILE_ENTRY::collect()
+/**
+  This updates the statistics for this moment of time.  It captures the state
+  of the running system, so later we can compare points in time and infer what
+  happened in the mean time.  It should only be called immediately upon
+  instantiation of this PROF_MEASUREMENT.
+
+  @todo  Implement resource capture for OSes not like BSD.
+*/
+void PROF_MEASUREMENT::collect()
 {
   time_usecs= (double) my_getsystime() / 10.0;  /* 1 sec was 1e7, now is 1e6 */
 #ifdef HAVE_GETRUSAGE
@@ -207,28 +225,13 @@ void PROFILE_ENTRY::collect()
 #endif
 }
 
-QUERY_PROFILE::QUERY_PROFILE(PROFILING *profiling_arg, char *query_source_arg,
-                             uint query_length_arg)
-  :profiling(profiling_arg), server_query_id(0), profiling_query_id(0),
-  query_source(NULL)
-{
-  profile_end= &profile_start;
-  set_query_source(query_source_arg, query_length_arg);
-}
 
-void QUERY_PROFILE::set_query_source(char *query_source_arg, 
-                                     uint query_length_arg)
+QUERY_PROFILE::QUERY_PROFILE(PROFILING *profiling_arg, const char *status_arg)
+  :profiling(profiling_arg), profiling_query_id(0), query_source(NULL)
 {
-  if (! profiling->enabled)
-    return;
-
-  /* Truncate to avoid DoS attacks. */
-  uint length= min(MAX_QUERY_LENGTH, query_length_arg); 
-  /* TODO?: Provide a way to include the full text, as in  SHOW PROCESSLIST. */
-
-  DBUG_ASSERT(query_source == NULL);
-  if (query_source_arg != NULL)
-    query_source= my_strndup(query_source_arg, length, MYF(0));
+  profile_start= new PROF_MEASUREMENT(this, status_arg);
+  entries.push_back(profile_start);
+  profile_end= profile_start;
 }
 
 QUERY_PROFILE::~QUERY_PROFILE()
@@ -240,61 +243,44 @@ QUERY_PROFILE::~QUERY_PROFILE()
     my_free(query_source, MYF(0));
 }
 
-void QUERY_PROFILE::status(const char *status_arg,
-                     const char *function_arg= NULL,
-                     const char *file_arg= NULL, unsigned int line_arg= 0)
+/**
+  @todo  Provide a way to include the full text, as in  SHOW PROCESSLIST.
+*/
+void QUERY_PROFILE::set_query_source(char *query_source_arg,
+                                     uint query_length_arg)
 {
-  THD *thd= profiling->thd;
-  PROFILE_ENTRY *prof;
-  DBUG_ENTER("QUERY_PROFILE::status");
+  /* Truncate to avoid DoS attacks. */
+  uint length= min(MAX_QUERY_LENGTH, query_length_arg);
 
-  /* Blank status.  Just return, and thd->proc_info will be set blank later. */
-  if (unlikely(status_arg == NULL))
-    DBUG_VOID_RETURN;
+  DBUG_ASSERT(query_source == NULL); /* we don't leak memory */
+  if (query_source_arg != NULL)
+    query_source= my_strndup(query_source_arg, length, MYF(0));
+}
 
-  /* If thd->proc_info is currently set to status_arg, don't profile twice. */
-  if (likely((thd->proc_info != NULL) && 
-      ((thd->proc_info == status_arg) || 
-       (strcmp(thd->proc_info, status_arg) == 0))))
-  {
-    DBUG_VOID_RETURN;
-  }
+void QUERY_PROFILE::new_status(const char *status_arg,
+                               const char *function_arg, const char *file_arg,
+                               unsigned int line_arg)
+{
+  PROF_MEASUREMENT *prof;
+  DBUG_ENTER("QUERY_PROFILE::status");
 
-  /* Is this the same query as our profile currently contains? */
-  if (unlikely((thd->query_id != server_query_id) && !thd->spcont))
-    reset();
+  DBUG_ASSERT(status_arg != NULL);
 
-  if (function_arg && file_arg) 
-  {
-    if ((profile_end= prof= new PROFILE_ENTRY(this, status_arg, function_arg, 
-                                              file_arg, line_arg)))
-      entries.push_back(prof);
-  } 
+  if ((function_arg != NULL) && (file_arg != NULL))
+    prof= new PROF_MEASUREMENT(this, status_arg, function_arg, file_arg, line_arg);
   else
-  {
-    if ((profile_end= prof= new PROFILE_ENTRY(this, status_arg)))
+    prof= new PROF_MEASUREMENT(this, status_arg);
+
+  profile_end= prof;
   entries.push_back(prof);
-  }
 
   DBUG_VOID_RETURN;
 }
 
-void QUERY_PROFILE::reset()
-{
-  DBUG_ENTER("QUERY_PROFILE::reset");
-  if (likely(profiling->thd->query_id != server_query_id))
-  {
-    server_query_id= profiling->thd->query_id; /* despite name, is global */
-    profile_start.collect();
 
-    while (! entries.is_empty())
-      delete entries.pop();
-  }
-  DBUG_VOID_RETURN;
-}
 
 PROFILING::PROFILING()
-  :profile_id_counter(1), keeping(TRUE), enabled(FALSE), current(NULL), last(NULL)
+  :profile_id_counter(1), current(NULL), last(NULL)
 {
 }
 
@@ -307,54 +293,97 @@ PROFILING::~PROFILING()
     delete current;
 }
 
+/**
+  A new state is given, and that signals the profiler to start a new
+  timed step for the current query's profile.
+
+  @param  status_arg  name of this step
+  @param  function_arg  calling function (usually supplied from compiler)
+  @param  function_arg  calling file (usually supplied from compiler)
+  @param  function_arg  calling line number (usually supplied from compiler)
+*/
 void PROFILING::status_change(const char *status_arg,
                               const char *function_arg,
                               const char *file_arg, unsigned int line_arg)
 {
   DBUG_ENTER("PROFILING::status_change");
 
-  if (unlikely(enabled))
-  {
-    if (unlikely(current == NULL))
-      reset();
+  if (status_arg == NULL)  /* We don't know how to handle that */
+    DBUG_VOID_RETURN;
 
-    DBUG_ASSERT(current != NULL);
+  if (current == NULL)  /* This profile was already discarded. */
+    DBUG_VOID_RETURN;
 
-    current->status(status_arg, function_arg, file_arg, line_arg);
-  }
+  if (unlikely(enabled))
+    current->new_status(status_arg, function_arg, file_arg, line_arg);
 
-  thd->proc_info= status_arg;
   DBUG_VOID_RETURN;
 }
 
-void PROFILING::store()
+/**
+  Prepare to start processing a new query.  It is an error to do this
+  if there's a query already in process; nesting is not supported.
+
+  @param  initial_state  (optional) name of period before first state change
+*/
+void PROFILING::start_new_query(const char *initial_state)
 {
-  DBUG_ENTER("PROFILING::store");
+  DBUG_ENTER("PROFILING::start_new_query");
 
-  /* Already stored */
-  if (unlikely((last != NULL) && 
-               (current != NULL) && 
-               (last->server_query_id == current->server_query_id)))
+  /* This should never happen unless the server is radically altered. */
+  if (unlikely(current != NULL))
   {
-    DBUG_VOID_RETURN;
+    DBUG_PRINT("warning", ("profiling code was asked to start a new query "
+                           "before the old query was finished.  This is "
+                           "probably a bug."));
+    finish_current_query();
   }
 
-  if (likely(((thd)->options & OPTION_PROFILING) == 0))
+  enabled= (((thd)->options & OPTION_PROFILING) != 0);
+
+  if (! enabled) DBUG_VOID_RETURN;
+
+  DBUG_ASSERT(current == NULL);
+  current= new QUERY_PROFILE(this, initial_state);
+
+  DBUG_VOID_RETURN;
+}
+
+/**
+  Throw away the current profile, because it's useless or unwanted
+  or corrupted.
+*/
+void PROFILING::discard_current_query()
+{
+  DBUG_ENTER("PROFILING::discard_current_profile");
+
+  delete current;
+  current= NULL;
+
   DBUG_VOID_RETURN;
+}
 
+/**
+  Try to save the current profile entry, clean up the data if it shouldn't be
+  saved, and maintain the profile history size.  Naturally, this may not
+  succeed if the profile was previously discarded, and that's expected.
+*/
+void PROFILING::finish_current_query()
+{
+  DBUG_ENTER("PROFILING::finish_current_profile");
   if (current != NULL)
   {
-    if (keeping && 
-        (enabled) &&                                    /* ON at start? */
-        (((thd)->options & OPTION_PROFILING) != 0) &&   /* and ON at end? */
-        (current->query_source != NULL) && 
-        (current->query_source[0] != '\0') && 
-        (!current->entries.is_empty())) 
+    /* The last fence-post, so we can support the span before this. */
+    status_change("ending", NULL, NULL, 0);
+
+    if ((enabled) &&                                    /* ON at start? */
+        ((thd->options & OPTION_PROFILING) != 0) &&   /* and ON at end? */
+        (! current->entries.is_empty()))
     {
       current->profiling_query_id= next_profile_id();   /* assign an id */
 
-      last= current; /* never contains something that is not in the history. */
       history.push_back(current);
+      last= current; /* never contains something that is not in the history. */
       current= NULL;
     }
     else
@@ -364,42 +393,13 @@ void PROFILING::store()
     }
   }
 
-  DBUG_ASSERT(current == NULL);
-  if (enabled)
-    current= new QUERY_PROFILE(this, thd->query, thd->query_length);
-
+  /* Maintain the history size. */
   while (history.elements > thd->variables.profiling_history_size)
     delete history.pop();
 
   DBUG_VOID_RETURN;
 }
 
-/**
-  Store and clean up the old information and get ready to hold info about this
-  new query.  This is called very often so it must be very lightweight if
-  profiling is not active.
-*/
-void PROFILING::reset()
-{
-  DBUG_ENTER("PROFILING::reset");
-
-  store();
-
-  if (likely(((thd)->options & OPTION_PROFILING) == 0))
-  {
-    enabled= FALSE;
-    DBUG_VOID_RETURN;
-  }
-  else
-    enabled= TRUE;
-
-  if (current != NULL)
-    current->reset();
-  keep();
-
-  DBUG_VOID_RETURN;
-}
-
 bool PROFILING::show_profiles()
 {
   DBUG_ENTER("PROFILING::show_profiles");
@@ -432,8 +432,8 @@ bool PROFILING::show_profiles()
 
     String elapsed;
 
-    PROFILE_ENTRY *ps= &prof->profile_start;
-    PROFILE_ENTRY *pe=  prof->profile_end;
+    PROF_MEASUREMENT *ps= prof->profile_start;
+    PROF_MEASUREMENT *pe= prof->profile_end;
 
     if (++idx <= unit->offset_limit_cnt)
       continue;
@@ -457,16 +457,18 @@ bool PROFILING::show_profiles()
   DBUG_RETURN(FALSE);
 }
 
-/*
-  This is an awful hack to let prepared statements tell us the query
-  that they're executing.
+/**
+  At a point in execution where we know the query source, save the text
+  of it in the query profile.
+
+  This must be called exactly once per descrete statement.
 */
 void PROFILING::set_query_source(char *query_source_arg, uint query_length_arg)
 {
   DBUG_ENTER("PROFILING::set_query_source");
 
-  /* We can't get this query source through normal means. */
-  DBUG_ASSERT((thd->query == NULL) || (thd->query_length == 0));
+  if (! enabled)
+    DBUG_VOID_RETURN;
 
   if (current != NULL)
     current->set_query_source(query_source_arg, query_length_arg);
@@ -475,7 +477,6 @@ void PROFILING::set_query_source(char *query_source_arg, uint query_length_arg)
   DBUG_VOID_RETURN;
 }
 
-
 /**
   Fill the information schema table, "query_profile", as defined in show.cc .
   There are two ways to get to this function:  Selecting from the information
@@ -495,7 +496,6 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond)
        history_iterator= history.iterator_next(history_iterator))
   {
     query= history.iterator_value(history_iterator);
-    PROFILE_ENTRY *previous= &(query->profile_start);
 
     /*
       Because we put all profiling info into a table that may be reordered, let
@@ -505,7 +505,7 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond)
     ulonglong seq;
 
     void *entry_iterator;
-    PROFILE_ENTRY *entry;
+    PROF_MEASUREMENT *entry, *previous= NULL;
     /* ...and for each query, go through all its state-change steps. */
     for (seq= 0, entry_iterator= query->entries.new_iterator();
          entry_iterator != NULL;
@@ -514,6 +514,9 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond)
     {
       entry= query->entries.iterator_value(entry_iterator);
 
+      /* Skip the first.  We count spans of fence, not fence-posts. */
+      if (previous == NULL) continue;
+
       if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)
       {
         /*
@@ -559,29 +562,32 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond)
       table->field[2]->store(previous->status, strlen(previous->status),
                              system_charset_info);
 
-      my_decimal duration;
+      my_decimal duration_decimal;
       double2my_decimal(E_DEC_FATAL_ERROR,
                         (entry->time_usecs-previous->time_usecs)/(1000.0*1000),
-                        &duration);
-      table->field[3]->store_decimal(&duration);
+                        &duration_decimal);
+
+      table->field[3]->store_decimal(&duration_decimal);
+
 
 #ifdef HAVE_GETRUSAGE
 
-      my_decimal cpu_utime, cpu_stime;
+      my_decimal cpu_utime_decimal, cpu_stime_decimal;
+
       double2my_decimal(E_DEC_FATAL_ERROR,
                         RUSAGE_DIFF_USEC(entry->rusage.ru_utime,
                                          previous->rusage.ru_utime) /
                                                         (1000.0*1000),
-                        &cpu_utime);
+                        &cpu_utime_decimal);
 
       double2my_decimal(E_DEC_FATAL_ERROR,
                         RUSAGE_DIFF_USEC(entry->rusage.ru_stime,
                                          previous->rusage.ru_stime) /
                                                         (1000.0*1000),
-                        &cpu_stime);
+                        &cpu_stime_decimal);
 
-      table->field[4]->store_decimal(&cpu_utime);
-      table->field[5]->store_decimal(&cpu_stime);
+      table->field[4]->store_decimal(&cpu_utime_decimal);
+      table->field[5]->store_decimal(&cpu_stime_decimal);
       table->field[4]->set_notnull();
       table->field[5]->set_notnull();
 #else
@@ -640,14 +646,15 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond)
       /* TODO: Add swap info for non-BSD systems */
 #endif
 
-      if ((entry->function != NULL) && (entry->file != NULL))
+      /* Emit the location that started this step, not that ended it. */
+      if ((previous->function != NULL) && (previous->file != NULL))
       {
-        table->field[15]->store(entry->function, strlen(entry->function),
+        table->field[15]->store(previous->function, strlen(previous->function),
                         system_charset_info);
         table->field[15]->set_notnull();
-        table->field[16]->store(entry->file, strlen(entry->file), system_charset_info);
+        table->field[16]->store(previous->file, strlen(previous->file), system_charset_info);
         table->field[16]->set_notnull();
-        table->field[17]->store(entry->line, true);
+        table->field[17]->store(previous->line, true);
         table->field[17]->set_notnull();
       }
 

sql/sql_profile.h

@@ -62,7 +62,7 @@ int make_profile_table_for_show(THD *thd, ST_SCHEMA_TABLE *schema_table);
 #endif
 
 
-class PROFILE_ENTRY;
+class PROF_MEASUREMENT;
 class QUERY_PROFILE;
 class PROFILING;
 
@@ -176,7 +176,7 @@ public:
 /**
   A single entry in a single profile.
 */
-class PROFILE_ENTRY
+class PROF_MEASUREMENT
 {
 private:
   friend class QUERY_PROFILE;
@@ -195,22 +195,22 @@ private:
   double time_usecs;
   char *allocated_status_memory;
 
-  void set_status(const char *status_arg, const char *function_arg, 
+  void set_label(const char *status_arg, const char *function_arg, 
                   const char *file_arg, unsigned int line_arg);
   void clean_up();
   
-  PROFILE_ENTRY();
-  PROFILE_ENTRY(QUERY_PROFILE *profile_arg, const char *status_arg);
-  PROFILE_ENTRY(QUERY_PROFILE *profile_arg, const char *status_arg,
+  PROF_MEASUREMENT();
+  PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);
+  PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,
                 const char *function_arg,
                 const char *file_arg, unsigned int line_arg);
-  ~PROFILE_ENTRY();
+  ~PROF_MEASUREMENT();
   void collect();
 };
 
 
 /**
-  The full profile for a single query, and includes multiple PROFILE_ENTRY
+  The full profile for a single query, and includes multiple PROF_MEASUREMENT
   objects.
 */
 class QUERY_PROFILE
@@ -220,21 +220,21 @@ private:
 
   PROFILING *profiling;
 
-  query_id_t server_query_id;           /* Global id. */
   query_id_t profiling_query_id;        /* Session-specific id. */
   char *query_source;
-  PROFILE_ENTRY profile_start;
-  PROFILE_ENTRY *profile_end;
-  Queue<PROFILE_ENTRY> entries;
 
+  PROF_MEASUREMENT *profile_start;
+  PROF_MEASUREMENT *profile_end;
+  Queue<PROF_MEASUREMENT> entries;
 
-  QUERY_PROFILE(PROFILING *profiling_arg, char *query_source_arg, uint query_length_arg);
+
+  QUERY_PROFILE(PROFILING *profiling_arg, const char *status_arg);
   ~QUERY_PROFILE();
 
   void set_query_source(char *query_source_arg, uint query_length_arg);
 
   /* Add a profile status change to the current profile. */
-  void status(const char *status_arg,
+  void new_status(const char *status_arg,
               const char *function_arg,
               const char *file_arg, unsigned int line_arg);
 
@@ -252,7 +252,7 @@ private:
 class PROFILING
 {
 private:
-  friend class PROFILE_ENTRY;
+  friend class PROF_MEASUREMENT;
   friend class QUERY_PROFILE;
 
   /* 
@@ -274,39 +274,12 @@ public:
   ~PROFILING();
   void set_query_source(char *query_source_arg, uint query_length_arg);
 
-  /** Reset the current profile and state of profiling for the next query. */
-  void reset();
+  void start_new_query(const char *initial_state= "starting");
 
-  /**
-    Do we intend to keep the currently collected profile?
+  void discard_current_query();
 
-    We don't keep profiles for some commands, such as SHOW PROFILE, SHOW
-    PROFILES, and some SQLCOM commands which aren't useful to profile.  The
-    keep() and discard() functions can be called many times, only the final
-    setting when the query finishes is used to decide whether to discard the
-    profile.
+  void finish_current_query();
 
-    The default is to keep the profile for all queries.
-  */
-  inline void keep()    { keeping= true; };
-
-  /**
-    Do we intend to keep the currently collected profile?
-    @see keep()
-  */
-  inline void discard() { keeping= false; };
-
-  /** 
-    Stash this profile in the profile history and remove the oldest
-    profile if the history queue is full, as defined by the 
-    profiling_history_size system variable.
-  */
-  void store();
-
-  /**
-    Called with every update of the status via thd_proc_info() , and is
-    therefore the main hook into the profiling code.
-  */
   void status_change(const char *status_arg,
                      const char *function_arg,
                      const char *file_arg, unsigned int line_arg);

sql/sql_show.cc

@@ -5361,17 +5361,24 @@ ST_SCHEMA_TABLE *get_schema_table(enum enum_schema_tables schema_table_idx)
 }
 
 
-/*
-  Create information_schema table using schema_table data
+/**
+  Create information_schema table using schema_table data.
 
-  SYNOPSIS
-    create_schema_table()
+  @note
+    For MYSQL_TYPE_DECIMAL fields only, the field_length member has encoded
+    into it two numbers, based on modulus of base-10 numbers.  In the ones
+    position is the number of decimals.  Tens position is unused.  In the
+    hundreds and thousands position is a two-digit decimal number representing
+    length.  Encode this value with  (decimals*100)+length  , where
+    0<decimals<10 and 0<=length<100 .
+
+  @param
     thd	       	          thread handler
+  @param
     schema_table          pointer to 'shema_tables' element
 
-  RETURN
-    #	                  Pointer to created table
-    0	                  Can't create table
+  @retval  \#             Pointer to created table
+  @retval  NULL           Can't create table
 */
 
 TABLE *create_schema_table(THD *thd, TABLE_LIST *table_list)