# name : response-time-distribution.patch # introduced : 12 # maintainer : Oleg # #!!! notice !!! # Any small change to this file in the main branch # should be done or reviewed by the maintainer! diff -ruN a/CMakeLists.txt b/CMakeLists.txt --- a/CMakeLists.txt 2010-12-03 20:58:24.000000000 +0300 +++ b/CMakeLists.txt 2011-01-16 20:11:28.000000000 +0300 @@ -165,7 +165,12 @@ OPTION (WITH_UNIT_TESTS "Compile MySQL with unit tests" ON) MARK_AS_ADVANCED(CYBOZU BACKUP_TEST WITHOUT_SERVER DISABLE_SHARED) - +OPTION(WITHOUT_RESPONSE_TIME_DISTRIBUTION "If we want to have response_time_distribution" OFF) +IF(WITHOUT_RESPONSE_TIME_DISTRIBUTION) +ELSE() +ADD_DEFINITIONS(-DHAVE_RESPONSE_TIME_DISTRIBUTION) +ENDIF() + OPTION(ENABLE_DEBUG_SYNC "Enable debug sync (debug builds only)" ON) IF(ENABLE_DEBUG_SYNC) SET(CMAKE_CXX_FLAGS_DEBUG "${CMAKE_CXX_FLAGS_DEBUG} -DENABLED_DEBUG_SYNC") diff -ruN a/include/mysql_com.h b/include/mysql_com.h --- a/include/mysql_com.h 2010-12-03 20:58:24.000000000 +0300 +++ b/include/mysql_com.h 2011-01-16 18:53:58.000000000 +0300 @@ -137,10 +137,11 @@ #define REFRESH_FAST 32768 /* Intern flag */ /* RESET (remove all queries) from query cache */ -#define REFRESH_QUERY_CACHE 65536 -#define REFRESH_QUERY_CACHE_FREE 0x20000L /* pack query cache */ -#define REFRESH_DES_KEY_FILE 0x40000L -#define REFRESH_USER_RESOURCES 0x80000L +#define REFRESH_QUERY_CACHE 65536 +#define REFRESH_QUERY_CACHE_FREE 0x20000L /* pack query cache */ +#define REFRESH_DES_KEY_FILE 0x40000L +#define REFRESH_USER_RESOURCES 0x80000L +#define REFRESH_QUERY_RESPONSE_TIME 0x100000L /* response time distibution */ #define CLIENT_LONG_PASSWORD 1 /* new more secure passwords */ #define CLIENT_FOUND_ROWS 2 /* Found instead of affected rows */ diff -ruN a/patch_info/response-time-distribution.info b/patch_info/response-time-distribution.info --- a/patch_info/response-time-distribution.info 1970-01-01 03:00:00.000000000 +0300 +++ b/patch_info/response-time-distribution.info 2011-01-16 18:53:59.000000000 +0300 @@ -0,0 +1,9 @@ +File=response-time-distribution.patch +Name=Response time distribution +Version=1.0 +Author=Percona +License=GPL +Comment= +Changelog +2010-07-02 first version avaliable +2010-09-15 add column 'total' diff -ruN a/sql/CMakeLists.txt b/sql/CMakeLists.txt --- a/sql/CMakeLists.txt 2010-12-03 20:58:26.000000000 +0300 +++ b/sql/CMakeLists.txt 2011-01-16 18:53:59.000000000 +0300 @@ -51,7 +51,7 @@ message.h mf_iocache.cc my_decimal.cc ../sql-common/my_time.c mysqld.cc net_serv.cc keycaches.cc ../sql-common/client_plugin.c - opt_range.cc opt_range.h opt_sum.cc + opt_range.cc opt_range.h query_response_time.h opt_sum.cc ../sql-common/pack.c parse_file.cc password.c procedure.cc protocol.cc records.cc repl_failsafe.cc rpl_filter.cc set_var.cc slave.cc sp.cc sp_cache.cc sp_head.cc sp_pcontext.cc @@ -59,7 +59,7 @@ sql_cache.cc sql_class.cc sql_client.cc sql_crypt.cc sql_crypt.h sql_cursor.cc sql_db.cc sql_delete.cc sql_derived.cc sql_do.cc sql_error.cc sql_handler.cc sql_help.cc sql_insert.cc sql_lex.cc - sql_list.cc sql_load.cc sql_manager.cc sql_parse.cc + sql_list.cc sql_load.cc sql_manager.cc sql_parse.cc query_response_time.cc sql_partition.cc sql_plugin.cc sql_prepare.cc sql_rename.cc debug_sync.cc debug_sync.h sql_repl.cc sql_select.cc sql_show.cc sql_state.c sql_string.cc diff -ruN a/sql/handler.h b/sql/handler.h --- a/sql/handler.h 2011-01-16 18:53:33.000000000 +0300 +++ b/sql/handler.h 2011-01-16 18:54:00.000000000 +0300 @@ -580,6 +580,7 @@ SCH_PROFILES, SCH_REFERENTIAL_CONSTRAINTS, SCH_PROCEDURES, + SCH_QUERY_RESPONSE_TIME, SCH_SCHEMATA, SCH_SCHEMA_PRIVILEGES, SCH_SESSION_STATUS, diff -ruN a/sql/lex.h b/sql/lex.h --- a/sql/lex.h 2010-12-03 20:58:26.000000000 +0300 +++ b/sql/lex.h 2011-01-16 18:54:01.000000000 +0300 @@ -426,6 +426,7 @@ { "PURGE", SYM(PURGE)}, { "QUARTER", SYM(QUARTER_SYM)}, { "QUERY", SYM(QUERY_SYM)}, + { "QUERY_RESPONSE_TIME", SYM(QUERY_RESPONSE_TIME_SYM)}, { "QUICK", SYM(QUICK)}, { "RANGE", SYM(RANGE_SYM)}, { "READ", SYM(READ_SYM)}, diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc --- a/sql/mysqld.cc 2011-01-16 18:53:35.000000000 +0300 +++ b/sql/mysqld.cc 2011-01-17 02:22:27.000000000 +0300 @@ -69,6 +69,8 @@ #include "debug_sync.h" #include "sql_callback.h" +#include "query_response_time.h" + #ifdef WITH_PERFSCHEMA_STORAGE_ENGINE #include "../storage/perfschema/pfs_server.h" #endif /* WITH_PERFSCHEMA_STORAGE_ENGINE */ @@ -603,7 +605,7 @@ MY_LOCALE *my_default_lc_messages; MY_LOCALE *my_default_lc_time_names; -SHOW_COMP_OPTION have_ssl, have_symlink, have_dlopen, have_query_cache; +SHOW_COMP_OPTION have_ssl, have_symlink, have_dlopen, have_query_cache, have_response_time_distribution; SHOW_COMP_OPTION have_geometry, have_rtree_keys; SHOW_COMP_OPTION have_crypt, have_compress; SHOW_COMP_OPTION have_profiling; @@ -904,6 +906,10 @@ my_bool opt_enable_shared_memory; HANDLE smem_event_connect_request= 0; #endif +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION +ulong opt_query_response_time_range_base = QRT_DEFAULT_BASE; +my_bool opt_query_response_time_stats= 0; +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION my_bool opt_use_ssl = 0; char *opt_ssl_ca= NULL, *opt_ssl_capath= NULL, *opt_ssl_cert= NULL, @@ -1472,6 +1478,9 @@ my_free(opt_bin_logname); bitmap_free(&temp_pool); free_max_user_conn(); +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + query_response_time_free(); +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION #ifdef HAVE_REPLICATION end_slave_list(); #endif @@ -3925,6 +3934,9 @@ if (!DEFAULT_ERRMSGS[0][0]) unireg_abort(1); +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + query_response_time_init(); +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION /* We have to initialize the storage engines before CSV logging */ if (ha_init()) { @@ -6797,6 +6809,11 @@ #else have_query_cache=SHOW_OPTION_NO; #endif +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + have_response_time_distribution= SHOW_OPTION_YES; +#else // HAVE_RESPONSE_TIME_DISTRIBUTION + have_response_time_distribution= SHOW_OPTION_NO; +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION #ifdef HAVE_SPATIAL have_geometry=SHOW_OPTION_YES; #else diff -ruN a/sql/mysqld.h b/sql/mysqld.h --- a/sql/mysqld.h 2011-01-16 18:53:35.000000000 +0300 +++ b/sql/mysqld.h 2011-01-17 02:08:20.000000000 +0300 @@ -98,6 +98,10 @@ extern bool opt_disable_networking, opt_skip_show_db; extern bool opt_skip_name_resolve; extern bool opt_ignore_builtin_innodb; +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION +extern ulong opt_query_response_time_range_base; +extern my_bool opt_query_response_time_stats; +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION extern my_bool opt_character_set_client_handshake; extern bool volatile abort_loop; extern bool in_bootstrap; diff -ruN a/sql/query_response_time.cc b/sql/query_response_time.cc --- a/sql/query_response_time.cc 1970-01-01 03:00:00.000000000 +0300 +++ b/sql/query_response_time.cc 2011-01-17 02:13:08.000000000 +0300 @@ -0,0 +1,372 @@ +#include "mysql_version.h" +#ifdef __FreeBSD__ +#include +#include +#endif // __FreeBSD__ +#include "my_global.h" +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION +#include "mysql_com.h" +#include "rpl_tblmap.h" +#include "table.h" +#include "field.h" +#include "sql_show.h" +#include "query_response_time.h" + +#define TIME_STRING_POSITIVE_POWER_LENGTH QRT_TIME_STRING_POSITIVE_POWER_LENGTH +#define TIME_STRING_NEGATIVE_POWER_LENGTH 6 +#define TOTAL_STRING_POSITIVE_POWER_LENGTH QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH +#define TOTAL_STRING_NEGATIVE_POWER_LENGTH 6 +#define MINIMUM_BASE 2 +#define MAXIMUM_BASE QRT_MAXIMUM_BASE +#define POSITIVE_POWER_FILLER QRT_POSITIVE_POWER_FILLER +#define NEGATIVE_POWER_FILLER QRT_NEGATIVE_POWER_FILLER +#define STRING_OVERFLOW QRT_STRING_OVERFLOW +#define TIME_OVERFLOW QRT_TIME_OVERFLOW +#define DEFAULT_BASE QRT_DEFAULT_BASE + +#define do_xstr(s) do_str(s) +#define do_str(s) #s +#define do_format(filler,width) "%" filler width "lld" +/* + Format strings for snprintf. Generate from: + POSITIVE_POWER_FILLER and TIME_STRING_POSITIVE_POWER_LENGTH + NEFATIVE_POWER_FILLER and TIME_STRING_NEGATIVE_POWER_LENGTH +*/ +#define TIME_STRING_POSITIVE_POWER_FORMAT do_format(POSITIVE_POWER_FILLER,do_xstr(TIME_STRING_POSITIVE_POWER_LENGTH)) +#define TIME_STRING_NEGATIVE_POWER_FORMAT do_format(NEGATIVE_POWER_FILLER,do_xstr(TIME_STRING_NEGATIVE_POWER_LENGTH)) +#define TIME_STRING_FORMAT TIME_STRING_POSITIVE_POWER_FORMAT "." TIME_STRING_NEGATIVE_POWER_FORMAT + +#define TOTAL_STRING_POSITIVE_POWER_FORMAT do_format(POSITIVE_POWER_FILLER,do_xstr(TOTAL_STRING_POSITIVE_POWER_LENGTH)) +#define TOTAL_STRING_NEGATIVE_POWER_FORMAT do_format(NEGATIVE_POWER_FILLER,do_xstr(TOTAL_STRING_NEGATIVE_POWER_LENGTH)) +#define TOTAL_STRING_FORMAT TOTAL_STRING_POSITIVE_POWER_FORMAT "." TOTAL_STRING_NEGATIVE_POWER_FORMAT + +#define TIME_STRING_LENGTH QRT_TIME_STRING_LENGTH +#define TIME_STRING_BUFFER_LENGTH (TIME_STRING_LENGTH + 1 /* '\0' */) + +#define TOTAL_STRING_LENGTH QRT_TOTAL_STRING_LENGTH +#define TOTAL_STRING_BUFFER_LENGTH (TOTAL_STRING_LENGTH + 1 /* '\0' */) + +/* + Calculate length of "log linear" + 1) + (MINIMUM_BASE ^ result) <= (10 ^ STRING_POWER_LENGTH) < (MINIMUM_BASE ^ (result + 1)) + + 2) + (MINIMUM_BASE ^ result) <= (10 ^ STRING_POWER_LENGTH) + and + (MINIMUM_BASE ^ (result + 1)) > (10 ^ STRING_POWER_LENGTH) + + 3) + result <= LOG(MINIMUM_BASE, 10 ^ STRING_POWER_LENGTH)= STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10) + result + 1 > LOG(MINIMUM_BASE, 10 ^ STRING_POWER_LENGTH)= STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10) + + 4) STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10) - 1 < result <= STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10) + + MINIMUM_BASE= 2 always, LOG(MINIMUM_BASE,10)= 3.3219280948873626, result= (int)3.3219280948873626 * STRING_POWER_LENGTH + + Last counter always use for time overflow +*/ +#define POSITIVE_POWER_COUNT ((int)(3.32192809 * TIME_STRING_POSITIVE_POWER_LENGTH)) +#define NEGATIVE_POWER_COUNT ((int)(3.32192809 * TIME_STRING_NEGATIVE_POWER_LENGTH)) +#define OVERALL_POWER_COUNT (NEGATIVE_POWER_COUNT + 1 + POSITIVE_POWER_COUNT) + +#define MILLION ((unsigned long)1000 * 1000) + +namespace query_response_time +{ + +class utility +{ +public: + utility() : m_base(0) + { + m_max_dec_value= MILLION; + for(int i= 0; TIME_STRING_POSITIVE_POWER_LENGTH > i; ++i) + m_max_dec_value *= 10; + setup(DEFAULT_BASE); + } +public: + uint base() const { return m_base; } + uint negative_count() const { return m_negative_count; } + uint positive_count() const { return m_positive_count; } + uint bound_count() const { return m_bound_count; } + ulonglong max_dec_value() const { return m_max_dec_value; } + ulonglong bound(uint index) const { return m_bound[ index ]; } +public: + void setup(uint base) + { + if(base != m_base) + { + m_base= base; + + const ulonglong million= 1000 * 1000; + ulonglong value= million; + m_negative_count= 0; + while(value > 0) + { + m_negative_count += 1; + value /= m_base; + } + m_negative_count -= 1; + + value= million; + m_positive_count= 0; + while(value < m_max_dec_value) + { + m_positive_count += 1; + value *= m_base; + } + m_bound_count= m_negative_count + m_positive_count; + + value= million; + for(uint i= 0; i < m_negative_count; ++i) + { + value /= m_base; + m_bound[m_negative_count - i - 1]= value; + } + value= million; + for(uint i= 0; i < m_positive_count; ++i) + { + m_bound[m_negative_count + i]= value; + value *= m_base; + } + } + } +private: + uint m_base; + uint m_negative_count; + uint m_positive_count; + uint m_bound_count; + ulonglong m_max_dec_value; /* for TIME_STRING_POSITIVE_POWER_LENGTH=7 is 10000000 */ + ulonglong m_bound[OVERALL_POWER_COUNT]; +}; + +void print_time(char* buffer, std::size_t buffer_size, std::size_t string_positive_power_length, const char* format, uint64 value) +{ + memset(buffer,'X',buffer_size); + buffer[string_positive_power_length]= '.'; + ulonglong second= (value / MILLION); + ulonglong microsecond= (value % MILLION); + std::size_t result_length= snprintf(buffer,buffer_size,format,second,microsecond); + if(result_length < 0) + { + assert(sizeof(STRING_OVERFLOW) <= buffer_size); + memcpy(buffer, STRING_OVERFLOW, sizeof(STRING_OVERFLOW)); + return; + } + buffer[result_length]= 0; +} +#ifdef __x86_64__ +typedef uint64 TimeCounter; +void add_time_atomic(TimeCounter* counter, uint64 time) +{ + __sync_fetch_and_add(counter,time); +} +#endif // __x86_64__ +#ifdef __i386__ +inline uint32 get_high(uint64 value) +{ + return ((value >> 32) << 32); +} +inline uint32 get_low(uint64 value) +{ + return ((value << 32) >> 32); +} +#ifdef __FreeBSD__ +inline bool compare_and_swap(volatile uint32 *target, uint32 old, uint32 new_value) +{ + return atomic_cmpset_32(target,old,new_value); +} +#else // __FreeBSD__ +inline bool compare_and_swap(volatile uint32* target, uint32 old, uint32 new_value) +{ + return __sync_bool_compare_and_swap(target,old,new_value); +} +#endif // __FreeBSD__ +class TimeCounter +{ +public: + TimeCounter& operator=(uint64 time) + { + this->m_high= get_high(time); + this->m_low= get_low(time); + return *this; + } + operator uint64() const + { + return ((static_cast(m_high) << 32) + static_cast(m_low)); + } + void add(uint64 time) + { + uint32 time_high = get_high(time); + uint32 time_low = get_low(time); + uint64 time_low64= time_low; + while(true) + { + uint32 old_low= this->m_low; + uint64 old_low64= old_low; + + uint64 new_low64= old_low64 + time_low64; + uint32 new_low= (get_low(new_low64)); + bool add_high= (get_high(new_low64) != 0); + + if(!compare_and_swap(&m_low,old_low,new_low)) + { + continue; + } + if(add_high) + { + ++time_high; + } + if(time_high > 0) + { + __sync_fetch_and_add(&m_high,time_high); + } + break; + } + } +private: + uint32 m_low; + uint32 m_high; +}; +void add_time_atomic(TimeCounter* counter, uint64 time) +{ + counter->add(time); +} +#endif // __i386__ + +class time_collector +{ +public: + time_collector(utility& u) : m_utility(&u) + { + } + uint32 count(uint index) const { return m_count[index]; } + uint64 total(uint index) const { return m_total[index]; } +public: + void flush() + { + memset(&m_count,0,sizeof(m_count)); + memset((void*)&m_total,0,sizeof(m_total)); + } + void collect(uint64 time) + { + bool no_collect= false; + DBUG_EXECUTE_IF("response_time_distribution_log_only_more_300_milliseconds", { \ + no_collect= time < 300 * 1000; \ + }); + if(no_collect) return; + int i= 0; + for(int count= m_utility->bound_count(); count > i; ++i) + { + if(m_utility->bound(i) > time) + { + __sync_fetch_and_add(&(m_count[i]),(uint32)1); + add_time_atomic(&(m_total[i]),time); + break; + } + } + } +private: + utility* m_utility; + uint32 m_count[OVERALL_POWER_COUNT + 1]; + TimeCounter m_total[OVERALL_POWER_COUNT + 1]; +}; + +class collector +{ +public: + collector() : m_time(m_utility) + { + m_utility.setup(DEFAULT_BASE); + m_time.flush(); + } +public: + void flush() + { + m_utility.setup(opt_query_response_time_range_base); + m_time.flush(); + } + int fill(THD* thd, TABLE_LIST *tables, COND *cond) + { + DBUG_ENTER("fill_schema_query_response_time"); + TABLE *table= static_cast(tables->table); + Field **fields= table->field; + for(uint i= 0, count= bound_count() + 1 /* with overflow */; count > i; ++i) + { + char time[TIME_STRING_BUFFER_LENGTH]; + char total[TOTAL_STRING_BUFFER_LENGTH]; + if(i == bound_count()) + { + assert(sizeof(TIME_OVERFLOW) <= TIME_STRING_BUFFER_LENGTH); + assert(sizeof(TIME_OVERFLOW) <= TOTAL_STRING_BUFFER_LENGTH); + memcpy(time,TIME_OVERFLOW,sizeof(TIME_OVERFLOW)); + memcpy(total,TIME_OVERFLOW,sizeof(TIME_OVERFLOW)); + } + else + { + print_time(time,sizeof(time),TIME_STRING_POSITIVE_POWER_LENGTH,TIME_STRING_FORMAT,this->bound(i)); + print_time(total,sizeof(total),TOTAL_STRING_POSITIVE_POWER_LENGTH,TOTAL_STRING_FORMAT,this->total(i)); + } + fields[0]->store(time,strlen(time),system_charset_info); + fields[1]->store(this->count(i)); + fields[2]->store(total,strlen(total),system_charset_info); + if (schema_table_store_record(thd, table)) + { + DBUG_RETURN(1); + } + } + DBUG_RETURN(0); + } + void collect(ulonglong time) + { + m_time.collect(time); + } + uint bound_count() const + { + return m_utility.bound_count(); + } + ulonglong bound(uint index) + { + return m_utility.bound(index); + } + ulonglong count(uint index) + { + return m_time.count(index); + } + ulonglong total(uint index) + { + return m_time.total(index); + } +private: + utility m_utility; + time_collector m_time; +}; + +static collector g_collector; + +} // namespace query_response_time + +void query_response_time_init() +{ +} + +void query_response_time_free() +{ + query_response_time::g_collector.flush(); +} + +void query_response_time_flush() +{ + query_response_time::g_collector.flush(); +} +void query_response_time_collect(ulonglong query_time) +{ + query_response_time::g_collector.collect(query_time); +} + +int query_response_time_fill(THD* thd, TABLE_LIST *tables, COND *cond) +{ + return query_response_time::g_collector.fill(thd,tables,cond); +} +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION diff -ruN a/sql/query_response_time.h b/sql/query_response_time.h --- a/sql/query_response_time.h 1970-01-01 03:00:00.000000000 +0300 +++ b/sql/query_response_time.h 2011-01-17 02:13:34.000000000 +0300 @@ -0,0 +1,71 @@ +#ifndef QUERY_RESPONSE_TIME_H +#define QUERY_RESPONSE_TIME_H + +/* + Settings for query response time +*/ + +/* + Maximum string length for (10 ^ (-1 * QRT_STRING_NEGATIVE_POWER_LENGTH)) in text representation. + Example: for 6 is 0.000001 + Always 2 + + Maximum string length for (10 ^ (QRT_STRING_POSITIVE_POWER_LENGTH + 1) - 1) in text representation. + Example: for 7 is 9999999.0 +*/ +#define QRT_TIME_STRING_POSITIVE_POWER_LENGTH 7 +#define QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH 7 + +/* + Minimum base for log - ALWAYS 2 + Maximum base for log: +*/ +#define QRT_MAXIMUM_BASE 1000 + +/* + Filler for whole number (positive power) + Example: for + QRT_POSITIVE_POWER_FILLER ' ' + QRT_POSITIVE_POWER_LENGTH 7 + and number 7234 result is: + ' 7234' +*/ +#define QRT_POSITIVE_POWER_FILLER " " +/* + Filler for fractional number. Similiary to whole number +*/ +#define QRT_NEGATIVE_POWER_FILLER "0" + +/* + Message if string overflow (string overflow - internal error, this string say about bug in QRT) +*/ +#define QRT_STRING_OVERFLOW "TOO BIG STRING" + +/* + Message if time too big for statistic collecting (very long query) +*/ +#define QRT_TIME_OVERFLOW "TOO LONG" + +#define QRT_DEFAULT_BASE 10 + +#define QRT_TIME_STRING_LENGTH \ + max( (QRT_TIME_STRING_POSITIVE_POWER_LENGTH + 1 /* '.' */ + 6 /*QRT_TIME_STRING_NEGATIVE_POWER_LENGTH*/), \ + max( (sizeof(QRT_TIME_OVERFLOW) - 1), \ + (sizeof(QRT_STRING_OVERFLOW) - 1) ) ) + +#define QRT_TOTAL_STRING_LENGTH \ + max( (QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH + 1 /* '.' */ + 6 /*QRT_TOTAL_STRING_NEGATIVE_POWER_LENGTH*/), \ + max( (sizeof(QRT_TIME_OVERFLOW) - 1), \ + (sizeof(QRT_STRING_OVERFLOW) - 1) ) ) + +extern ST_SCHEMA_TABLE query_response_time_table; + +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION +extern void query_response_time_init (); +extern void query_response_time_free (); +extern void query_response_time_flush (); +extern void query_response_time_collect(ulonglong query_time); +extern int query_response_time_fill (THD* thd, TABLE_LIST *tables, COND *cond); +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION + +#endif // QUERY_RESPONSE_TIME_H diff -ruN a/sql/set_var.h b/sql/set_var.h --- a/sql/set_var.h 2010-12-03 20:58:26.000000000 +0300 +++ b/sql/set_var.h 2011-01-17 02:20:59.000000000 +0300 @@ -293,6 +293,7 @@ extern SHOW_COMP_OPTION have_ssl, have_symlink, have_dlopen; extern SHOW_COMP_OPTION have_query_cache; +extern SHOW_COMP_OPTION have_response_time_distribution; extern SHOW_COMP_OPTION have_geometry, have_rtree_keys; extern SHOW_COMP_OPTION have_crypt; extern SHOW_COMP_OPTION have_compress; diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc --- a/sql/sql_parse.cc 2011-01-16 18:53:35.000000000 +0300 +++ b/sql/sql_parse.cc 2011-01-17 02:15:09.000000000 +0300 @@ -88,6 +88,7 @@ #include "sp_cache.h" #include "events.h" #include "sql_trigger.h" +#include "query_response_time.h" #include "transaction.h" #include "sql_audit.h" #include "sql_prepare.h" @@ -1483,22 +1484,36 @@ Do not log administrative statements unless the appropriate option is set. */ + #ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + if (opt_query_response_time_stats || thd->enable_slow_log) +#else // HAVE_RESPONSE_TIME_DISTRIBUTION if (thd->enable_slow_log) +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION { - ulonglong end_utime_of_query= thd->current_utime(); - thd_proc_info(thd, "logging slow query"); - - if (((thd->server_status & SERVER_QUERY_WAS_SLOW) || - ((thd->server_status & - (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && - opt_log_queries_not_using_indexes && - !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))) && - thd->examined_row_count >= thd->variables.min_examined_row_limit) + ulonglong end_utime_of_query = thd->current_utime(); + ulonglong query_execution_time = end_utime_of_query - thd->utime_after_lock; +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + if(opt_query_response_time_stats) + { + query_response_time_collect(query_execution_time); + } +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION + if (thd->enable_slow_log) { thd_proc_info(thd, "logging slow query"); - thd->status_var.long_query_count++; - slow_log_print(thd, thd->query(), thd->query_length(), - end_utime_of_query); + + if (((thd->server_status & SERVER_QUERY_WAS_SLOW) || + ((thd->server_status & + (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && + opt_log_queries_not_using_indexes && + !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))) && + thd->examined_row_count >= thd->variables.min_examined_row_limit) + { + thd_proc_info(thd, "logging slow query"); + thd->status_var.long_query_count++; + slow_log_print(thd, thd->query(), thd->query_length(), + end_utime_of_query); + } } } DBUG_VOID_RETURN; @@ -1617,6 +1632,7 @@ case SCH_CHARSETS: case SCH_ENGINES: case SCH_COLLATIONS: + case SCH_QUERY_RESPONSE_TIME: case SCH_COLLATION_CHARACTER_SET_APPLICABILITY: case SCH_USER_PRIVILEGES: case SCH_SCHEMA_PRIVILEGES: diff -ruN a/sql/sql_reload.cc b/sql/sql_reload.cc --- a/sql/sql_reload.cc 2010-12-03 20:58:26.000000000 +0300 +++ b/sql/sql_reload.cc 2011-01-17 02:16:19.000000000 +0300 @@ -25,7 +25,7 @@ #include "hostname.h" // hostname_cache_refresh #include "sql_repl.h" // reset_master, reset_slave #include "debug_sync.h" - +#include "query_response_time.h" /** Reload/resets privileges and the different caches. @@ -282,6 +282,12 @@ #endif if (options & REFRESH_USER_RESOURCES) reset_mqh((LEX_USER *) NULL, 0); /* purecov: inspected */ +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + if (options & REFRESH_QUERY_RESPONSE_TIME) + { + query_response_time_flush(); + } +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION if (*write_to_binlog != -1) *write_to_binlog= tmp_write_to_binlog; /* diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc --- a/sql/sql_show.cc 2011-01-16 18:53:35.000000000 +0300 +++ b/sql/sql_show.cc 2011-01-17 02:17:44.000000000 +0300 @@ -50,6 +50,7 @@ #include "event_data_objects.h" #endif #include +#include "query_response_time.h" #include "lock.h" // MYSQL_OPEN_IGNORE_FLUSH #include "debug_sync.h" #include "datadict.h" // dd_frm_type() @@ -7688,6 +7689,14 @@ */ +ST_FIELD_INFO query_response_time_fields_info[] = + { + {"time", QRT_TIME_STRING_LENGTH, MYSQL_TYPE_STRING, 0, 0, "", SKIP_OPEN_TABLE }, + {"count", MY_INT32_NUM_DECIMAL_DIGITS, MYSQL_TYPE_LONG, 0, MY_I_S_UNSIGNED, "", SKIP_OPEN_TABLE }, + {"total", QRT_TIME_STRING_LENGTH, MYSQL_TYPE_STRING, 0, 0, "", SKIP_OPEN_TABLE }, + {0, 0, MYSQL_TYPE_STRING, 0, 0, 0, SKIP_OPEN_TABLE } + }; + ST_SCHEMA_TABLE schema_tables[]= { {"CHARACTER_SETS", charsets_fields_info, create_schema_table, @@ -7741,6 +7750,13 @@ 1, 9, 0, OPTIMIZE_I_S_TABLE|OPEN_TABLE_ONLY}, {"ROUTINES", proc_fields_info, create_schema_table, fill_schema_proc, make_proc_old_format, 0, -1, -1, 0, 0}, +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + {"QUERY_RESPONSE_TIME", query_response_time_fields_info, create_schema_table, + query_response_time_fill, make_old_format, 0, -1, -1, 0, 0}, +#else + {"QUERY_RESPONSE_TIME", query_response_time_fields_info, create_schema_table, + 0, make_old_format, 0, -1, -1, 0, 0}, +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION {"SCHEMATA", schema_fields_info, create_schema_table, fill_schema_schemata, make_schemata_old_format, 0, 1, -1, 0, 0}, {"SCHEMA_PRIVILEGES", schema_privileges_fields_info, create_schema_table, diff -ruN a/sql/sql_yacc.yy b/sql/sql_yacc.yy --- a/sql/sql_yacc.yy 2011-01-16 18:53:34.000000000 +0300 +++ b/sql/sql_yacc.yy 2011-01-17 02:19:03.000000000 +0300 @@ -1193,6 +1193,7 @@ %token PURGE %token QUARTER_SYM %token QUERY_SYM +%token QUERY_RESPONSE_TIME_SYM %token QUICK %token RANGE_SYM /* SQL-2003-R */ %token READS_SYM /* SQL-2003-R */ @@ -11089,6 +11090,15 @@ { Lex->sql_command = SQLCOM_SHOW_SLAVE_STAT; } + | QUERY_RESPONSE_TIME_SYM wild_and_where + { +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + LEX *lex= Lex; + lex->sql_command= SQLCOM_SELECT; + if (prepare_schema_table(YYTHD, lex, 0, SCH_QUERY_RESPONSE_TIME)) + MYSQL_YYABORT; +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION + } | CREATE PROCEDURE_SYM sp_name { LEX *lex= Lex; @@ -11325,6 +11335,12 @@ { Lex->type|= REFRESH_STATUS; } | SLAVE { Lex->type|= REFRESH_SLAVE; } + | QUERY_RESPONSE_TIME_SYM + { +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION + Lex->type|= REFRESH_QUERY_RESPONSE_TIME; +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION + } | MASTER_SYM { Lex->type|= REFRESH_MASTER; } | DES_KEY_FILE @@ -12610,6 +12626,7 @@ | PROXY_SYM {} | QUARTER_SYM {} | QUERY_SYM {} + | QUERY_RESPONSE_TIME_SYM {} | QUICK {} | READ_ONLY_SYM {} | REBUILD_SYM {} diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc --- a/sql/sys_vars.cc 2011-01-16 18:53:35.000000000 +0300 +++ b/sql/sys_vars.cc 2011-01-17 02:19:53.000000000 +0300 @@ -49,6 +49,7 @@ #include "../storage/perfschema/pfs_server.h" #endif /* WITH_PERFSCHEMA_STORAGE_ENGINE */ +#include "query_response_time.h" /* This forward declaration is needed because including sql_base.h causes further includes. [TODO] Eliminate this forward declaration @@ -1791,6 +1792,26 @@ DEFAULT(FALSE)); #endif /* HAVE_QUERY_CACHE */ + +static Sys_var_have Sys_have_response_time_distribution( + "have_response_time_distribution", "have_response_time_distribution", + READ_ONLY GLOBAL_VAR(have_response_time_distribution), NO_CMD_LINE); + +#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION +static Sys_var_mybool Sys_query_response_time_stats( + "query_response_time_stats", "Enable or disable query response time statisics collecting", + GLOBAL_VAR(opt_query_response_time_stats), CMD_LINE(OPT_ARG), + DEFAULT(FALSE)); + +static Sys_var_ulong Sys_query_response_time_range_base( + "query_response_time_range_base", + "Select base of log for query_response_time ranges. WARNING: variable change affect only after flush", + GLOBAL_VAR(opt_query_response_time_range_base), + CMD_LINE(REQUIRED_ARG), VALID_RANGE(2, QRT_MAXIMUM_BASE), + DEFAULT(QRT_DEFAULT_BASE), + BLOCK_SIZE(1)); +#endif // HAVE_RESPONSE_TIME_DISTRIBUTION + static Sys_var_mybool Sys_secure_auth( "secure_auth", "Disallow authentication for accounts that have old (pre-4.1) "