From: Date: March 15 2007 1:20am Subject: bk commit into 5.0 tree (cmiller:1.2421) BUG#27060 List-Archive: http://lists.mysql.com/commits/21961 X-Bug: 27060 Message-Id: <20070315002046.30CB18304C@zippy> 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 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 */