diff -ur mysql-5.0.37/include/my_time.h mysql-5.0.37-microslow/include/my_time.h --- mysql-5.0.37/include/my_time.h 2007-03-05 14:21:02.000000000 -0500 +++ mysql-5.0.37-microslow/include/my_time.h 2007-06-06 05:55:08.000000000 -0400 @@ -133,7 +133,7 @@ int my_date_to_str(const MYSQL_TIME *l_time, char *to); int my_datetime_to_str(const MYSQL_TIME *l_time, char *to); int my_TIME_to_str(const MYSQL_TIME *l_time, char *to); - +ulonglong my_timer(ulonglong *ltime, ulonglong frequency); C_MODE_END #endif /* _my_time_h_ */ diff -ur mysql-5.0.37/scripts/mysqldumpslow.sh mysql-5.0.37-microslow/scripts/mysqldumpslow.sh --- mysql-5.0.37/scripts/mysqldumpslow.sh 2007-03-05 14:21:40.000000000 -0500 +++ mysql-5.0.37-microslow/scripts/mysqldumpslow.sh 2007-06-06 05:55:08.000000000 -0400 @@ -83,8 +83,8 @@ s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//; my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('',''); - s/^# Query_time: (\d+) Lock_time: (\d+) Rows_sent: (\d+).*\n//; - my ($t, $l, $r) = ($1, $2, $3); + s/^# Query_time: (\d+(\.\d+)?) Lock_time: (\d+(\.\d+)?) Rows_sent: (\d+(\.\d+)?).*\n//; + my ($t, $l, $r) = ($1, $3, $5); $t -= $l unless $opt{l}; # remove fluff that mysqld writes to log when it (re)starts: diff -ur mysql-5.0.37/sql/log.cc mysql-5.0.37-microslow/sql/log.cc --- mysql-5.0.37/sql/log.cc 2007-03-05 14:21:42.000000000 -0500 +++ mysql-5.0.37-microslow/sql/log.cc 2007-06-06 05:55:08.000000000 -0400 @@ -1929,10 +1929,11 @@ */ bool MYSQL_LOG::write(THD *thd,const char *query, uint query_length, - time_t query_start_arg) + time_t query_start_arg, ulonglong query_start_timer) { bool error=0; time_t current_time; + ulonglong current_timer; if (!is_open()) return 0; DBUG_ENTER("MYSQL_LOG::write"); @@ -1960,7 +1961,7 @@ localtime_r(¤t_time,&tm_tmp); start=&tm_tmp; /* Note that my_b_write() assumes it knows the length for this */ - sprintf(buff,"# Time: %02d%02d%02d %2d:%02d:%02d\n", + sprintf(buff,"# Time: %02d%02d%02d %2d:%02d:%02d ", start->tm_year % 100, start->tm_mon+1, start->tm_mday, @@ -1979,13 +1980,16 @@ (uint) -1) tmp_errno=errno; } - if (query_start_arg) + if (query_start_timer) { + char buf[2][20]; + ulonglong current_timer= my_timer(¤t_timer, frequency); + sprintf(buf[0], "%.6f", (current_timer - query_start_timer) / 1000000.0); + sprintf(buf[1], "%.6f", (thd->timer_after_lock - query_start_timer) / 1000000.0); /* For slow query log */ if (my_b_printf(&log_file, - "# Query_time: %lu Lock_time: %lu Rows_sent: %lu Rows_examined: %lu\n", - (ulong) (current_time - query_start_arg), - (ulong) (thd->time_after_lock - query_start_arg), + "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu\n", + buf[0], buf[1], (ulong) thd->sent_row_count, (ulong) thd->examined_row_count) == (uint) -1) tmp_errno=errno; diff -ur mysql-5.0.37/sql/mysqld.cc mysql-5.0.37-microslow/sql/mysqld.cc --- mysql-5.0.37/sql/mysqld.cc 2007-03-05 14:21:11.000000000 -0500 +++ mysql-5.0.37-microslow/sql/mysqld.cc 2007-06-06 05:55:08.000000000 -0400 @@ -166,6 +166,7 @@ static void getvolumeID(BYTE *volumeName); #endif /* __NETWARE__ */ +ulonglong frequency= 0; #ifdef _AIX41 int initgroups(const char *,unsigned int); @@ -3378,6 +3379,8 @@ unireg_abort(1); } } + if (!QueryPerformanceFrequency((LARGE_INTEGER *)&frequency)) + frequency= 0; #endif /* __WIN__ */ if (init_common_variables(MYSQL_CONFIG_NAME, @@ -4607,7 +4610,7 @@ OPT_INTERACTIVE_TIMEOUT, OPT_JOIN_BUFF_SIZE, OPT_KEY_BUFFER_SIZE, OPT_KEY_CACHE_BLOCK_SIZE, OPT_KEY_CACHE_DIVISION_LIMIT, OPT_KEY_CACHE_AGE_THRESHOLD, - OPT_LONG_QUERY_TIME, + OPT_LONG_QUERY_TIME, OPT_MIN_EXAMINED_ROW_LIMIT, OPT_LOWER_CASE_TABLE_NAMES, OPT_MAX_ALLOWED_PACKET, OPT_MAX_BINLOG_CACHE_SIZE, OPT_MAX_BINLOG_SIZE, OPT_MAX_CONNECTIONS, OPT_MAX_CONNECT_ERRORS, @@ -5729,7 +5732,12 @@ "Log all queries that have taken more than long_query_time seconds to execute to file.", (gptr*) &global_system_variables.long_query_time, (gptr*) &max_system_variables.long_query_time, 0, GET_ULONG, - REQUIRED_ARG, 10, 1, LONG_TIMEOUT, 0, 1, 0}, + REQUIRED_ARG, 10000000, 0, LONG_TIMEOUT * 1000000, 0, 1, 0}, + {"min_examined_row_limit", OPT_MIN_EXAMINED_ROW_LIMIT, + "Don't log queries which examine less than min_examined_row_limit rows to file.", + (gptr*) &global_system_variables.min_examined_row_limit, + (gptr*) &max_system_variables.min_examined_row_limit, 0, GET_ULONG, + REQUIRED_ARG, 0, 1, ~0L, 0, 1L, 0}, {"lower_case_table_names", OPT_LOWER_CASE_TABLE_NAMES, "If set to 1 table names are stored in lowercase on disk and table names will be case-insensitive. Should be set to 2 if you are using a case insensitive file system", (gptr*) &lower_case_table_names, diff -ur mysql-5.0.37/sql/my_time.c mysql-5.0.37-microslow/sql/my_time.c --- mysql-5.0.37/sql/my_time.c 2007-03-05 14:21:21.000000000 -0500 +++ mysql-5.0.37-microslow/sql/my_time.c 2007-06-06 05:55:08.000000000 -0400 @@ -1219,3 +1219,37 @@ return 0; } +/* + int my_timer(ulonglong *ltime, ulonglong frequency) + + For performance measurement this function returns the number + of microseconds since the epoch (SVr4, BSD 4.3, POSIX 1003.1-2001) + or system start (Windows platforms). + + For windows platforms frequency value (obtained via + QueryPerformanceFrequency) has to be specified. The global frequency + value is set in mysqld.cc. + + If Windows platform doesn't support QueryPerformanceFrequency we will + obtain the time via GetClockCount, which supports microseconds only. +*/ + +ulonglong my_timer(ulonglong *ltime, ulonglong frequency) +{ + ulonglong newtime= 0; +#ifdef __WIN__ + if (frequency) + { + QueryPerformanceCounter((LARGE_INTEGER *)&newtime); + newtime/= (frequency * 1000000); + } else + newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */ +#else + struct timeval t; + gettimeofday(&t, NULL); + newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec; +#endif + if (ltime) + *ltime= newtime; + return newtime; +} diff -ur mysql-5.0.37/sql/set_var.cc mysql-5.0.37-microslow/sql/set_var.cc --- mysql-5.0.37/sql/set_var.cc 2007-03-05 14:21:24.000000000 -0500 +++ mysql-5.0.37-microslow/sql/set_var.cc 2007-06-06 05:55:08.000000000 -0400 @@ -214,7 +214,7 @@ sys_log_queries_not_using_indexes("log_queries_not_using_indexes", &opt_log_queries_not_using_indexes); sys_var_thd_ulong sys_log_warnings("log_warnings", &SV::log_warnings); -sys_var_thd_ulong sys_long_query_time("long_query_time", +sys_var_thd_microtime sys_long_query_time("long_query_time", &SV::long_query_time); sys_var_thd_bool sys_low_priority_updates("low_priority_updates", &SV::low_priority_updates, @@ -279,6 +279,8 @@ &SV::max_tmp_tables); sys_var_long_ptr sys_max_write_lock_count("max_write_lock_count", &max_write_lock_count); +sys_var_thd_ulong sys_min_examined_row_limit("min_examined_row_limit", + &SV::min_examined_row_limit); sys_var_thd_ulong sys_multi_range_count("multi_range_count", &SV::multi_range_count); sys_var_long_ptr sys_myisam_data_pointer_size("myisam_data_pointer_size", @@ -686,6 +688,7 @@ &sys_max_tmp_tables, &sys_max_user_connections, &sys_max_write_lock_count, + &sys_min_examined_row_limit, &sys_multi_range_count, &sys_myisam_data_pointer_size, &sys_myisam_max_sort_file_size, @@ -977,6 +980,7 @@ {sys_max_tmp_tables.name, (char*) &sys_max_tmp_tables, SHOW_SYS}, {sys_max_user_connections.name,(char*) &sys_max_user_connections, SHOW_SYS}, {sys_max_write_lock_count.name, (char*) &sys_max_write_lock_count,SHOW_SYS}, + {sys_min_examined_row_limit.name, (char*) &sys_min_examined_row_limit, SHOW_SYS}, {sys_multi_range_count.name, (char*) &sys_multi_range_count, SHOW_SYS}, {sys_myisam_data_pointer_size.name, (char*) &sys_myisam_data_pointer_size, SHOW_SYS}, {sys_myisam_max_sort_file_size.name, (char*) &sys_myisam_max_sort_file_size, @@ -1559,6 +1563,53 @@ return (byte*) &(thd->variables.*offset); } +void sys_var_thd_microtime::set_default(THD *thd, enum_var_type type) +{ + pthread_mutex_lock(&LOCK_global_system_variables); + global_system_variables.*offset= (ulonglong) option_limits->def_value; + pthread_mutex_unlock(&LOCK_global_system_variables); +} + +bool sys_var_thd_microtime::check(THD *thd, set_var *var) +{ + if (var->value->result_type() == DECIMAL_RESULT) + var->save_result.ulonglong_value= (ulonglong)(var->value->val_real() * 1000000); + else + var->save_result.ulonglong_value= (ulonglong)var->value->val_int() * 1000000; + return 0; +} + +byte *sys_var_thd_microtime::value_ptr(THD *thd, enum_var_type type, + LEX_STRING *base) +{ + if (type == OPT_GLOBAL) + return (byte*) &(global_system_variables.*offset); + return (byte*) &(thd->variables.*offset); +} + +bool sys_var_thd_microtime::update(THD *thd, set_var *var) +{ + ulonglong tmp= var->save_result.ulonglong_value; + + if (tmp > max_system_variables.*offset) + tmp= max_system_variables.*offset; + + if (option_limits) + tmp= getopt_ull_limit_value(tmp, option_limits); + + /* Lock is needed to make things safe on 32 bit systems */ + if (var->type == OPT_GLOBAL) + { + /* Lock is needed to make things safe on 32 bit systems */ + pthread_mutex_lock(&LOCK_global_system_variables); + global_system_variables.*offset= tmp; + pthread_mutex_unlock(&LOCK_global_system_variables); + } + else + thd->variables.*offset= (ulonglong) tmp; + + return 0; +} bool sys_var_thd_ha_rows::update(THD *thd, set_var *var) { diff -ur mysql-5.0.37/sql/set_var.h mysql-5.0.37-microslow/sql/set_var.h --- mysql-5.0.37/sql/set_var.h 2007-03-05 14:21:22.000000000 -0500 +++ mysql-5.0.37-microslow/sql/set_var.h 2007-06-06 05:55:08.000000000 -0400 @@ -121,6 +121,7 @@ }; + class sys_var_ulonglong_ptr :public sys_var { public: @@ -285,7 +286,6 @@ } }; - class sys_var_thd_ulong :public sys_var_thd { sys_check_func check_func; @@ -305,6 +305,23 @@ byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base); }; +class sys_var_thd_microtime :public sys_var_thd +{ +public: + ulonglong SV::*offset; + sys_var_thd_microtime(const char *name_arg, ulonglong SV::*offset_arg) + :sys_var_thd(name_arg), offset(offset_arg) + {} + bool update(THD *thd, set_var *var); + void set_default(THD *thd, enum_var_type type); + SHOW_TYPE type() { return SHOW_MICROTIME; } + byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base); + bool check(THD *thd, set_var *var); + bool check_update_type(Item_result type) + { + return type != INT_RESULT && type != DECIMAL_RESULT; + } +}; class sys_var_thd_ha_rows :public sys_var_thd { @@ -323,7 +340,6 @@ byte *value_ptr(THD *thd, enum_var_type type, LEX_STRING *base); }; - class sys_var_thd_ulonglong :public sys_var_thd { public: @@ -351,7 +367,6 @@ } }; - class sys_var_thd_bool :public sys_var_thd { public: diff -ur mysql-5.0.37/sql/sql_class.cc mysql-5.0.37-microslow/sql/sql_class.cc --- mysql-5.0.37/sql/sql_class.cc 2007-03-05 14:21:41.000000000 -0500 +++ mysql-5.0.37-microslow/sql/sql_class.cc 2007-06-06 05:55:08.000000000 -0400 @@ -177,7 +177,7 @@ Open_tables_state(refresh_version), lock_id(&main_lock_id), user_time(0), in_sub_stmt(0), global_read_lock(0), is_fatal_error(0), - rand_used(0), time_zone_used(0), + rand_used(0), time_zone_used(0), user_timer(0), last_insert_id_used(0), last_insert_id_used_bin_log(0), insert_id_used(0), clear_next_insert_id(0), in_lock_tables(0), bootstrap(0), derived_tables_processing(FALSE), spcont(NULL) diff -ur mysql-5.0.37/sql/sql_class.h mysql-5.0.37-microslow/sql/sql_class.h --- mysql-5.0.37/sql/sql_class.h 2007-03-05 14:21:40.000000000 -0500 +++ mysql-5.0.37-microslow/sql/sql_class.h 2007-06-06 05:55:08.000000000 -0400 @@ -42,6 +42,7 @@ extern char internal_table_name[2]; extern char empty_c_string[1]; extern const char **errmesg; +extern ulonglong frequency; #define TC_LOG_PAGE_SIZE 8192 #define TC_LOG_MIN_SIZE (3*TC_LOG_PAGE_SIZE) @@ -307,7 +308,7 @@ bool write(THD *thd, enum enum_server_command command, const char *format, ...) ATTRIBUTE_FORMAT(printf, 4, 5); bool write(THD *thd, const char *query, uint query_length, - time_t query_start=0); + time_t query_start=0, ulonglong query_start_timer=0); bool write(Log_event* event_info); // binary log write bool write(THD *thd, IO_CACHE *cache, Log_event *commit_event); @@ -501,13 +502,14 @@ ulong auto_increment_increment, auto_increment_offset; ulong bulk_insert_buff_size; ulong join_buff_size; - ulong long_query_time; + ulonglong long_query_time; ulong max_allowed_packet; ulong max_error_count; ulong max_length_for_sort_data; ulong max_sort_length; ulong max_tmp_tables; ulong max_insert_delayed_threads; + ulong min_examined_row_limit; ulong multi_range_count; ulong myisam_repair_threads; ulong myisam_sort_buff_size; @@ -1081,6 +1083,11 @@ class THD :public Statement, public Open_tables_state { +private: + inline ulonglong query_start_timer() { return start_timer; } + inline void set_timer() { if (user_timer) start_timer=timer_after_lock=user_timer; else timer_after_lock=my_timer(&start_timer, frequency); } + inline void end_timer() { my_timer(&start_timer, frequency); } + inline void lock_timer() { my_timer(&timer_after_lock, frequency); } public: /* Constant for THD::where initialization in the beginning of every query. @@ -1189,6 +1196,7 @@ */ const char *where; time_t start_time,time_after_lock,user_time; + ulonglong start_timer,timer_after_lock, user_timer; time_t connect_time,thr_create_time; // track down slow pthread_create thr_lock_type update_lock_default; delayed_insert *di; @@ -1504,11 +1512,11 @@ proc_info = old_msg; pthread_mutex_unlock(&mysys_var->mutex); } - inline time_t query_start() { query_start_used=1; return start_time; } - inline void set_time() { if (user_time) start_time=time_after_lock=user_time; else time_after_lock=time(&start_time); } - inline void end_time() { time(&start_time); } + inline time_t query_start() { query_start_timer(); query_start_used=1; return start_time; } + inline void set_time() { set_timer(); if (user_time) start_time=time_after_lock=user_time; else time_after_lock=time(&start_time); } + inline void end_time() { end_timer(); time(&start_time); } inline void set_time(time_t t) { time_after_lock=start_time=user_time=t; } - inline void lock_time() { time(&time_after_lock); } + inline void lock_time() { lock_timer(); time(&time_after_lock); } inline void insert_id(ulonglong id_arg) { last_insert_id= id_arg; diff -ur mysql-5.0.37/sql/sql_parse.cc mysql-5.0.37-microslow/sql/sql_parse.cc --- mysql-5.0.37/sql/sql_parse.cc 2007-03-05 14:21:40.000000000 -0500 +++ mysql-5.0.37-microslow/sql/sql_parse.cc 2007-06-06 06:51:30.000000000 -0400 @@ -20,6 +20,7 @@ #include #include #include +#include #ifdef HAVE_INNOBASE_DB #include "ha_innodb.h" @@ -2167,6 +2168,7 @@ return; // Don't set time for sub stmt start_of_query= thd->start_time; + ulonglong start_of_query_timer= thd->start_timer; thd->end_time(); // Set start time /* @@ -2177,22 +2179,22 @@ { thd_proc_info(thd, "logging slow query"); - if ((ulong) (thd->start_time - thd->time_after_lock) > - thd->variables.long_query_time || + if (((ulong) (thd->start_time - thd->time_after_lock) >= + thd->variables.long_query_time || (thd->server_status & - (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && + (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && (specialflag & SPECIAL_LOG_QUERIES_NOT_USING_INDEXES) && /* == SQLCOM_END unless this is a SHOW command */ - thd->lex->orig_sql_command == SQLCOM_END) - { + thd->lex->orig_sql_command == SQLCOM_END) && + thd->examined_row_count >= thd->variables.min_examined_row_limit ) + { thd_proc_info(thd, "logging slow query"); thd->status_var.long_query_count++; - mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query); + mysql_slow_log.write(thd, thd->query, thd->query_length, start_of_query, start_of_query_timer); } } } - /* Create a TABLE_LIST object for an INFORMATION_SCHEMA table. diff -ur mysql-5.0.37/sql/sql_show.cc mysql-5.0.37-microslow/sql/sql_show.cc --- mysql-5.0.37/sql/sql_show.cc 2007-03-05 14:21:21.000000000 -0500 +++ mysql-5.0.37-microslow/sql/sql_show.cc 2007-06-06 05:55:08.000000000 -0400 @@ -1461,6 +1461,9 @@ case SHOW_LONGLONG: end= longlong10_to_str(*(longlong*) value, buff, 10); break; + case SHOW_MICROTIME: + end= buff + sprintf(buff, "%.6f", (*(ulonglong*)value) / 1000000.0); + break; case SHOW_HA_ROWS: end= longlong10_to_str((longlong) *(ha_rows*) value, buff, 10); break; diff -ur mysql-5.0.37/sql/structs.h mysql-5.0.37-microslow/sql/structs.h --- mysql-5.0.37/sql/structs.h 2007-03-05 14:21:22.000000000 -0500 +++ mysql-5.0.37-microslow/sql/structs.h 2007-06-06 05:55:08.000000000 -0400 @@ -169,8 +169,8 @@ enum SHOW_TYPE { SHOW_UNDEF, - SHOW_LONG, SHOW_LONGLONG, SHOW_INT, SHOW_CHAR, SHOW_CHAR_PTR, - SHOW_DOUBLE_STATUS, + SHOW_LONG, SHOW_LONGLONG, SHOW_MICROTIME, SHOW_INT, SHOW_CHAR, + SHOW_CHAR_PTR, SHOW_DOUBLE_STATUS, SHOW_BOOL, SHOW_MY_BOOL, SHOW_OPENTABLES, SHOW_STARTTIME, SHOW_QUESTION, SHOW_LONG_CONST, SHOW_INT_CONST, SHOW_HAVE, SHOW_SYS, SHOW_HA_ROWS, SHOW_VARS, diff -ur mysql-5.0.37/sql-common/my_time.c mysql-5.0.37-microslow/sql-common/my_time.c --- mysql-5.0.37/sql-common/my_time.c 2007-03-05 14:21:21.000000000 -0500 +++ mysql-5.0.37-microslow/sql-common/my_time.c 2007-06-06 05:55:08.000000000 -0400 @@ -1219,3 +1219,37 @@ return 0; } +/* + int my_timer(ulonglong *ltime, ulonglong frequency) + + For performance measurement this function returns the number + of microseconds since the epoch (SVr4, BSD 4.3, POSIX 1003.1-2001) + or system start (Windows platforms). + + For windows platforms frequency value (obtained via + QueryPerformanceFrequency) has to be specified. The global frequency + value is set in mysqld.cc. + + If Windows platform doesn't support QueryPerformanceFrequency we will + obtain the time via GetClockCount, which supports microseconds only. +*/ + +ulonglong my_timer(ulonglong *ltime, ulonglong frequency) +{ + ulonglong newtime= 0; +#ifdef __WIN__ + if (frequency) + { + QueryPerformanceCounter((LARGE_INTEGER *)&newtime); + newtime/= (frequency * 1000000); + } else + newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */ +#else + struct timeval t; + gettimeofday(&t, NULL); + newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec; +#endif + if (ltime) + *ltime= newtime; + return newtime; +}