diff --git a/mysql-test/r/profiling.result b/mysql-test/r/profiling.result index b99870e3564..8c8ba01e8ac 100644 --- a/mysql-test/r/profiling.result +++ b/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 diff --git a/mysql-test/t/profiling.test b/mysql-test/t/profiling.test index c86ad60e59b..b0b56931385 100644 --- a/mysql-test/t/profiling.test +++ b/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; diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 1f48e55146b..bfac7a4ffb3 100644 --- a/sql/sql_parse.cc +++ b/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 diff --git a/sql/sql_profile.cc b/sql/sql_profile.cc index ab6666cd329..5b6e0187a92 100644 --- a/sql/sql_profile.cc +++ b/sql/sql_profile.cc @@ -14,21 +14,35 @@ 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_ = ""; /** Connects Information_Schema and Profiling. */ -int fill_query_profile_statistics_info(THD *thd, TABLE_LIST *tables, +int fill_query_profile_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond) { #if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER) @@ -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, - const char *function_arg, - const char *file_arg, unsigned int line_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) :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; @@ -163,7 +173,7 @@ void PROFILE_ENTRY::set_status(const char *status_arg, const char *function_arg, sizes[0]= (status_arg == NULL) ? 0 : strlen(status_arg) + 1; sizes[1]= (function_arg == NULL) ? 0 : strlen(function_arg) + 1; sizes[2]= (file_arg == NULL) ? 0 : strlen(file_arg) + 1; - + allocated_status_memory= (char *) my_malloc(sizes[0] + sizes[1] + sizes[2], MYF(0)); DBUG_ASSERT(allocated_status_memory != NULL); @@ -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) + +QUERY_PROFILE::QUERY_PROFILE(PROFILING *profiling_arg, const char *status_arg) + :profiling(profiling_arg), 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) -{ - 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; + /* Truncate to avoid DoS attacks. */ + uint length= min(MAX_QUERY_LENGTH, query_length_arg); + + 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)); +} + +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"); - /* Blank status. Just return, and thd->proc_info will be set blank later. */ - if (unlikely(status_arg == NULL)) - DBUG_VOID_RETURN; + DBUG_ASSERT(status_arg != NULL); - /* 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; - } + if ((function_arg != NULL) && (file_arg != NULL)) + prof= new PROF_MEASUREMENT(this, status_arg, function_arg, file_arg, line_arg); + else + prof= new PROF_MEASUREMENT(this, status_arg); - /* Is this the same query as our profile currently contains? */ - if (unlikely((thd->query_id != server_query_id) && !thd->spcont)) - reset(); - - 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); - } - else - { - if ((profile_end= prof= new PROFILE_ENTRY(this, status_arg))) - entries.push_back(prof); - } + 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,99 +293,113 @@ 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 (status_arg == NULL) /* We don't know how to handle that */ + DBUG_VOID_RETURN; + + if (current == NULL) /* This profile was already discarded. */ + DBUG_VOID_RETURN; + if (unlikely(enabled)) - { - if (unlikely(current == NULL)) - reset(); + current->new_status(status_arg, function_arg, file_arg, line_arg); - DBUG_ASSERT(current != NULL); - - current->status(status_arg, function_arg, file_arg, line_arg); - } - - thd->proc_info= status_arg; DBUG_VOID_RETURN; } -void PROFILING::store() -{ - DBUG_ENTER("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. - /* Already stored */ - if (unlikely((last != NULL) && - (current != NULL) && - (last->server_query_id == current->server_query_id))) + @param initial_state (optional) name of period before first state change +*/ +void PROFILING::start_new_query(const char *initial_state) +{ + DBUG_ENTER("PROFILING::start_new_query"); + + /* 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)) - DBUG_VOID_RETURN; + 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 { delete current; current= NULL; } } - - 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"); @@ -411,29 +411,29 @@ bool PROFILING::show_profiles() field_list.push_back(new Item_return_int("Duration", TIME_FLOAT_DIGITS-1, MYSQL_TYPE_DOUBLE)); field_list.push_back(new Item_empty_string("Query", 40)); - + if (thd->protocol->send_fields(&field_list, Protocol::SEND_NUM_ROWS | Protocol::SEND_EOF)) DBUG_RETURN(TRUE); - + SELECT_LEX *sel= &thd->lex->select_lex; SELECT_LEX_UNIT *unit= &thd->lex->unit; ha_rows idx= 0; Protocol *protocol= thd->protocol; unit->set_limit(sel); - + void *iterator; - for (iterator= history.new_iterator(); - iterator != NULL; + for (iterator= history.new_iterator(); + iterator != NULL; iterator= history.iterator_next(iterator)) { prof= history.iterator_value(iterator); 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; @@ -442,14 +442,14 @@ bool PROFILING::show_profiles() protocol->prepare_for_resend(); protocol->store((uint32)(prof->profiling_query_id)); - protocol->store((double)(pe->time_usecs - ps->time_usecs)/(1000.0*1000), + protocol->store((double)(pe->time_usecs - ps->time_usecs)/(1000.0*1000), (uint32) TIME_FLOAT_DIGITS-1, &elapsed); if (prof->query_source != NULL) - protocol->store(prof->query_source, strlen(prof->query_source), + protocol->store(prof->query_source, strlen(prof->query_source), system_charset_info); else protocol->store_null(); - + if (protocol->write()) DBUG_RETURN(TRUE); } @@ -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,11 +477,10 @@ 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 - schema, and a SHOW command. + schema, and a SHOW command. */ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond) { @@ -490,12 +491,11 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond) QUERY_PROFILE *query; /* Go through each query in this thread's stored history... */ void *history_iterator; - for (history_iterator= history.new_iterator(); - history_iterator != NULL; + for (history_iterator= history.new_iterator(); + history_iterator != NULL; 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,18 +505,21 @@ 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; + for (seq= 0, entry_iterator= query->entries.new_iterator(); + entry_iterator != NULL; entry_iterator= query->entries.iterator_next(entry_iterator), seq++, previous=entry, row_number++) { 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) { - /* + /* We got here via a SHOW command. That means that we stored information about the query we wish to show and that isn't in a WHERE clause at a higher level to filter out rows we @@ -556,43 +559,46 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond) 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), + table->field[2]->store(previous->status, strlen(previous->status), system_charset_info); - my_decimal duration; - double2my_decimal(E_DEC_FATAL_ERROR, + 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; - double2my_decimal(E_DEC_FATAL_ERROR, - RUSAGE_DIFF_USEC(entry->rusage.ru_utime, + 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, + double2my_decimal(E_DEC_FATAL_ERROR, RUSAGE_DIFF_USEC(entry->rusage.ru_stime, - previous->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 /* TODO: Add CPU-usage info for non-BSD systems */ #endif - + #ifdef HAVE_GETRUSAGE - table->field[6]->store((uint32)(entry->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 - + table->field[7]->store((uint32)(entry->rusage.ru_nivcsw - previous->rusage.ru_nivcsw)); table->field[7]->set_notnull(); #else @@ -600,32 +606,32 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond) #endif #ifdef HAVE_GETRUSAGE - table->field[8]->store((uint32)(entry->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 - + 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 - + 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 - + 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 - + 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 - + table->field[13]->store((uint32)(entry->rusage.ru_minflt - previous->rusage.ru_minflt), true); table->field[13]->set_notnull(); #else @@ -633,21 +639,22 @@ int PROFILING::fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond) #endif #ifdef HAVE_GETRUSAGE - table->field[14]->store((uint32)(entry->rusage.ru_nswap - + 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 */ #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), - system_charset_info); + 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(); } diff --git a/sql/sql_profile.h b/sql/sql_profile.h index 1a6ebcd0b0e..2483cb3cb6a 100644 --- a/sql/sql_profile.h +++ b/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 entries; + + PROF_MEASUREMENT *profile_start; + PROF_MEASUREMENT *profile_end; + Queue 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? - - 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. - - The default is to keep the profile for all queries. - */ - inline void keep() { keeping= true; }; + void discard_current_query(); - /** - Do we intend to keep the currently collected profile? - @see keep() - */ - inline void discard() { keeping= false; }; + void finish_current_query(); - /** - 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); diff --git a/sql/sql_show.cc b/sql/sql_show.cc index ed82cae247d..9aa081daf1e 100644 --- a/sql/sql_show.cc +++ b/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