diff -r 4636d2e0b0d0 patch_info/profiling_slow.info --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/patch_info/profiling_slow.info Fri Jul 03 15:40:29 2009 -0700 @@ -0,0 +1,9 @@ +File=profiling_slow.info +Name=profiling from SHOW PROFILE to slow.log +Version=1.0 +Author=Percona +License=GPL +Comment= +Changelog +2009-05-18 +Initial implementation diff -r 4636d2e0b0d0 sql/log.cc --- a/sql/log.cc Fri Jul 03 15:40:20 2009 -0700 +++ b/sql/log.cc Fri Jul 03 15:40:29 2009 -0700 @@ -2402,6 +2402,11 @@ tmp_errno=errno; } } + +#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER) + thd->profiling.print_current(&log_file); +#endif + if (thd->db && strcmp(thd->db,db)) { // Database changed if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1) diff -r 4636d2e0b0d0 sql/mysqld.cc --- a/sql/mysqld.cc Fri Jul 03 15:40:20 2009 -0700 +++ b/sql/mysqld.cc Fri Jul 03 15:40:29 2009 -0700 @@ -5052,6 +5052,8 @@ OPT_PORT_OPEN_TIMEOUT, OPT_MERGE, OPT_PROFILING, + OPT_PROFILING_SERVER, + OPT_PROFILING_USE_GETRUSAGE, OPT_SLOW_LOG, OPT_SLOW_QUERY_LOG_FILE, OPT_USE_GLOBAL_LONG_QUERY_TIME, @@ -5675,6 +5677,16 @@ (gptr*) &global_system_variables.profiling_history_size, (gptr*) &max_system_variables.profiling_history_size, 0, GET_ULONG, REQUIRED_ARG, 15, 0, 100, 0, 0, 0}, + {"profiling_server", OPT_PROFILING_SERVER, + "Enable profiling of all threads", + (gptr*) &global_system_variables.profiling_server, + (gptr*) &max_system_variables.profiling_server, 0, GET_BOOL, + OPT_ARG, 0, 0, 0, 0, 0, 0 }, + {"profiling_use_getrusage", OPT_PROFILING_USE_GETRUSAGE, + "Enable getrusage function call for profiling", + (gptr*) &global_system_variables.profiling_use_getrusage, + (gptr*) &max_system_variables.profiling_use_getrusage, 0, GET_BOOL, + OPT_ARG, 0, 0, 0, 0, 0, 0 }, #endif {"relay-log", OPT_RELAY_LOG, "The location and name to use for relay logs.", diff -r 4636d2e0b0d0 sql/set_var.cc --- a/sql/set_var.cc Fri Jul 03 15:40:20 2009 -0700 +++ b/sql/set_var.cc Fri Jul 03 15:40:29 2009 -0700 @@ -592,6 +592,10 @@ ulonglong(OPTION_PROFILING)); static sys_var_thd_ulong sys_profiling_history_size("profiling_history_size", &SV::profiling_history_size); +static sys_var_thd_bool sys_profiling_server("profiling_server", + &SV::profiling_server); +static sys_var_thd_bool sys_profiling_use_getrusage("profiling_use_getrusage", + &SV::profiling_use_getrusage); #endif /* Local state variables */ @@ -764,6 +768,8 @@ #if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER) &sys_profiling, &sys_profiling_history_size, + &sys_profiling_server, + &sys_profiling_use_getrusage, #endif &sys_pseudo_thread_id, &sys_query_alloc_block_size, @@ -1094,6 +1100,8 @@ #if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER) {sys_profiling.name, (char*) &sys_profiling, SHOW_SYS}, {sys_profiling_history_size.name, (char*) &sys_profiling_history_size, SHOW_SYS}, + {sys_profiling_server.name, (char*) &sys_profiling_server, SHOW_SYS}, + {sys_profiling_use_getrusage.name, (char*) &sys_profiling_use_getrusage, SHOW_SYS}, #endif {"protocol_version", (char*) &protocol_version, SHOW_INT}, {sys_query_alloc_block_size.name, (char*) &sys_query_alloc_block_size, diff -r 4636d2e0b0d0 sql/sql_class.h --- a/sql/sql_class.h Fri Jul 03 15:40:20 2009 -0700 +++ b/sql/sql_class.h Fri Jul 03 15:40:29 2009 -0700 @@ -550,6 +550,8 @@ ulong optimizer_search_depth; ulong preload_buff_size; ulong profiling_history_size; + my_bool profiling_server; + my_bool profiling_use_getrusage; ulong query_cache_type; ulong log_slow_rate_limit; ulong read_buff_size; diff -r 4636d2e0b0d0 sql/sql_profile.cc --- a/sql/sql_profile.cc Fri Jul 03 15:40:20 2009 -0700 +++ b/sql/sql_profile.cc Fri Jul 03 15:40:29 2009 -0700 @@ -221,9 +221,22 @@ */ void PROF_MEASUREMENT::collect() { + struct timespec tp; time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */ #ifdef HAVE_GETRUSAGE - getrusage(RUSAGE_SELF, &rusage); + if ((profile->get_profiling())->enabled_getrusage()) + getrusage(RUSAGE_SELF, &rusage); +#endif + +#ifdef HAVE_CLOCK_GETTIME + if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp))) + { + cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec; + } + else + { + cpu_time_usecs= 0; + } #endif } @@ -341,7 +354,7 @@ finish_current_query(); } - enabled= (((thd)->options & OPTION_PROFILING) != 0); + enabled= (((thd)->options & OPTION_PROFILING) != 0) || ( thd->variables.profiling_server ); if (! enabled) DBUG_VOID_RETURN; @@ -379,7 +392,8 @@ status_change("ending", NULL, NULL, 0); if ((enabled) && /* ON at start? */ - ((thd->options & OPTION_PROFILING) != 0) && /* and ON at end? */ + (((thd->options & OPTION_PROFILING) != 0) || + (thd->variables.profiling_server)) && /* and ON at end? */ (current->query_source != NULL) && (! current->entries.is_empty())) { @@ -480,6 +494,88 @@ DBUG_VOID_RETURN; } +bool PROFILING::enabled_getrusage() +{ + return thd->variables.profiling_use_getrusage; +} + +/** + Print output for current query to file +*/ + +int PROFILING::print_current(IO_CACHE *log_file) +{ + DBUG_ENTER("PROFILING::print_current"); + ulonglong row_number= 0; + char query_time_buff[22+7]; + char query_cpu_time_buff[22+7]; + + QUERY_PROFILE *query; + /* Get current query */ + if (current == NULL) + { + DBUG_RETURN(0); + } + + query= current; + + my_b_printf(log_file, "# PROFILE_VALUES "); + + void *entry_iterator; + PROF_MEASUREMENT *entry, *previous= NULL, *first= NULL; + /* ...and for each query, go through all its state-change steps. */ + for (entry_iterator= query->entries.new_iterator(); + entry_iterator != NULL; + entry_iterator= query->entries.iterator_next(entry_iterator), + 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) {first= entry; continue;} + + if (thd->lex->orig_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 + wish to exclude. + + Because that functionality isn't available in the server yet, + we must filter here, at the wrong level. Once one can con- + struct where and having conditions at the SQL layer, then this + condition should be ripped out. + */ + if (thd->lex->profile_query_id == 0) /* 0 == show final query */ + { + if (query != last) + continue; + } + else + { + if (thd->lex->profile_query_id != query->profiling_query_id) + continue; + } + } + + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", (entry->time_usecs-previous->time_usecs)/(1000.0*1000)); + snprintf(query_cpu_time_buff, sizeof(query_cpu_time_buff), "%.6f", (entry->cpu_time_usecs-previous->cpu_time_usecs)/(1000.0*1000*1000)); + my_b_printf(log_file, "%s: %s (cpu: %s), ", previous->status, query_time_buff, query_cpu_time_buff); + + } + + my_b_printf(log_file, "\n"); + if ((entry != NULL) && (first != NULL)) + { + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", (entry->time_usecs-first->time_usecs)/(1000.0*1000)); + snprintf(query_cpu_time_buff, sizeof(query_cpu_time_buff), "%.6f", (entry->cpu_time_usecs-first->cpu_time_usecs)/(1000.0*1000*1000)); + my_b_printf(log_file, "# PROFILE_TOTALS Total: %s (cpu: %s)\n", query_time_buff, query_cpu_time_buff); + } + + DBUG_RETURN(0); +} + /** 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 diff -r 4636d2e0b0d0 sql/sql_profile.h --- a/sql/sql_profile.h Fri Jul 03 15:40:20 2009 -0700 +++ b/sql/sql_profile.h Fri Jul 03 15:40:29 2009 -0700 @@ -193,6 +193,7 @@ unsigned int line; double time_usecs; + double cpu_time_usecs; char *allocated_status_memory; void set_label(const char *status_arg, const char *function_arg, @@ -243,6 +244,11 @@ /* Show this profile. This is called by PROFILING. */ bool show(uint options); + +public: + + inline PROFILING * get_profiling() { return profiling; }; + }; @@ -288,9 +294,11 @@ /* SHOW PROFILES */ bool show_profiles(); + bool enabled_getrusage(); /* ... from INFORMATION_SCHEMA.PROFILING ... */ int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond); + int print_current(IO_CACHE *log_file); }; # endif /* HAVE_PROFILING */