diff -r 7d9c3a18b9f3 include/my_sys.h --- a/include/my_sys.h Sat Jul 07 11:05:37 2007 +0200 +++ b/include/my_sys.h Sat Jul 07 13:40:09 2007 +0200 @@ -640,6 +640,7 @@ extern int my_redel(const char *from, co extern int my_redel(const char *from, const char *to, int MyFlags); extern int my_copystat(const char *from, const char *to, int MyFlags); extern char * my_filename(File fd); +extern ulonglong my_utime(ulonglong *utime, ulonglong frequency); #ifndef THREAD extern void dont_break(void); diff -r 7d9c3a18b9f3 mysys/Makefile.am --- a/mysys/Makefile.am Sat Jul 07 11:05:37 2007 +0200 +++ b/mysys/Makefile.am Sat Jul 07 13:23:57 2007 +0200 @@ -52,7 +52,8 @@ libmysys_a_SOURCES = my_init.c my_get my_gethostbyname.c rijndael.c my_aes.c sha1.c \ my_handler.c my_netware.c my_largepage.c \ my_memmem.c \ - my_windac.c my_access.c base64.c my_libwrap.c + my_windac.c my_access.c base64.c my_libwrap.c \ + my_utime.c EXTRA_DIST = thr_alarm.c thr_lock.c my_pthread.c my_thr_init.c \ thr_mutex.c thr_rwlock.c \ CMakeLists.txt mf_soundex.c \ diff -r 7d9c3a18b9f3 mysys/Makefile.in --- a/mysys/Makefile.in Sat Jul 07 11:05:37 2007 +0200 +++ b/mysys/Makefile.in Sat Jul 07 13:25:13 2007 +0200 @@ -120,7 +120,8 @@ am_libmysys_a_OBJECTS = my_init.$(OBJEXT my_aes.$(OBJEXT) sha1.$(OBJEXT) my_handler.$(OBJEXT) \ my_netware.$(OBJEXT) my_largepage.$(OBJEXT) \ my_memmem.$(OBJEXT) my_windac.$(OBJEXT) my_access.$(OBJEXT) \ - base64.$(OBJEXT) my_libwrap.$(OBJEXT) + base64.$(OBJEXT) my_libwrap.$(OBJEXT) \ + my_utime.$(OBJEXT) libmysys_a_OBJECTS = $(am_libmysys_a_OBJECTS) DEFAULT_INCLUDES = -I. -I$(srcdir) -I$(top_builddir) depcomp = $(SHELL) $(top_srcdir)/depcomp @@ -491,7 +492,8 @@ libmysys_a_SOURCES = my_init.c my_getwd. my_gethostbyname.c rijndael.c my_aes.c sha1.c \ my_handler.c my_netware.c my_largepage.c \ my_memmem.c \ - my_windac.c my_access.c base64.c my_libwrap.c + my_windac.c my_access.c base64.c my_libwrap.c \ + my_utime.c EXTRA_DIST = thr_alarm.c thr_lock.c my_pthread.c my_thr_init.c \ thr_mutex.c thr_rwlock.c \ @@ -682,6 +684,7 @@ distclean-compile: @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/tree.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/trie.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/typelib.Po@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/my_utime.Po@am__quote@ .c.o: @am__fastdepCC_TRUE@ if $(COMPILE) -MT $@ -MD -MP -MF "$(DEPDIR)/$*.Tpo" -c -o $@ $<; \ diff -r 7d9c3a18b9f3 mysys/my_utime.c --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/mysys/my_utime.c Sat Jul 07 15:30:12 2007 +0200 @@ -0,0 +1,43 @@ +#include +#include + +#include "my_global.h" + +/* + ulonglong my_utime(ulonglong *utime, 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_utime(ulonglong *utime, ulonglong frequency) +{ + ulonglong newtime= 0; +#if !defined(__WIN__) + struct timeval t; +#endif /* !defined(__WIN__) */ + +#if defined(__WIN__) + if (frequency) + { + QueryPerformanceCounter((LARGE_INTEGER *)&newtime); + newtime/= (frequency * 1000000); + } + else + newtime= (GetTickCount() * 1000; /* GetTickCount only returns milliseconds */ +#else /* defined(__WIN__) */ + gettimeofday(&t, NULL); + newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec; +#endif /* defined(__WIN__) */ + if (utime) + *utime= newtime; + return newtime; +} diff -r 7d9c3a18b9f3 sql/log.cc --- a/sql/log.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/log.cc Sat Jul 07 23:53:39 2007 +0200 @@ -524,8 +524,8 @@ err: user_host the pointer to the string with user@host info user_host_len length of the user_host string. this is computed once and passed to all general log event handlers - query_time Amount of time the query took to execute (in seconds) - lock_time Amount of time the query was locked (in seconds) + query_utime Amount of time the query took to execute (in microseconds) + lock_utime Amount of time the query was locked (in microseconds) is_command The flag, which determines, whether the sql_text is a query or an administrator command (these are treated differently by the old logging routines) @@ -545,9 +545,11 @@ bool Log_to_csv_event_handler:: bool Log_to_csv_event_handler:: log_slow(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, uint user_host_len, - longlong query_time, longlong lock_time, bool is_command, + ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len) { + longlong query_time,lock_time; + /* table variables */ TABLE *table= slow_log.table; CHARSET_INFO *client_cs= thd->variables.character_set_client; @@ -590,6 +592,8 @@ bool Log_to_csv_event_handler:: MYSQL_TIME t; t.neg= 0; + query_time= (longlong) (query_utime/1000000); + lock_time= (longlong) (lock_utime/1000000); /* fill in query_time field */ calc_time_from_sec(&t, (long) min(query_time, (longlong) TIME_MAX_VALUE_SECONDS), 0); if (table->field[2]->store_time(&t, MYSQL_TIMESTAMP_TIME)) @@ -694,12 +698,12 @@ bool Log_to_file_event_handler:: bool Log_to_file_event_handler:: log_slow(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, uint user_host_len, - longlong query_time, longlong lock_time, bool is_command, + ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len) { return mysql_slow_log.write(thd, current_time, query_start_arg, user_host, user_host_len, - query_time, lock_time, is_command, + query_utime, lock_utime, is_command, sql_text, sql_text_len); } @@ -915,7 +919,7 @@ bool LOGGER::flush_logs(THD *thd) */ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length, - time_t query_start_arg) + time_t query_start_arg, ulonglong query_ustart_arg) { bool error= FALSE; Log_event_handler **current_handler= slow_log_handler_list; @@ -923,9 +927,10 @@ bool LOGGER::slow_log_print(THD *thd, co char user_host_buff[MAX_USER_HOST_SIZE]; time_t current_time; + ulonglong current_utime; Security_context *sctx= thd->security_ctx; uint user_host_len= 0; - longlong query_time= 0, lock_time= 0; + ulonglong query_utime= 0, lock_utime= 0; /* Print the message to the buffer if we have slow log enabled @@ -934,9 +939,10 @@ bool LOGGER::slow_log_print(THD *thd, co if (*slow_log_handler_list) { current_time= time(NULL); + current_utime= my_utime(NULL, frequency); /* do not log slow queries from replication threads */ - if (thd->slave_thread) + if (thd->slave_thread && !opt_log_slow_slave_statements) return 0; lock(); @@ -956,8 +962,8 @@ bool LOGGER::slow_log_print(THD *thd, co if (query_start_arg) { - query_time= (longlong) (current_time - query_start_arg); - lock_time= (longlong) (thd->time_after_lock - query_start_arg); + query_utime= (ulonglong) (current_utime - query_ustart_arg); + lock_utime= (ulonglong) (thd->utime_after_lock - query_ustart_arg); } if (!query) @@ -970,7 +976,7 @@ bool LOGGER::slow_log_print(THD *thd, co while (*current_handler) error= (*current_handler++)->log_slow(thd, current_time, query_start_arg, user_host_buff, user_host_len, - query_time, lock_time, is_command, + query_utime, lock_utime, is_command, query, query_length) || error; unlock(); @@ -2187,8 +2193,8 @@ err: bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, - uint user_host_len, longlong query_time, - longlong lock_time, bool is_command, + uint user_host_len, ulonglong query_utime, + ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len) { bool error= 0; @@ -2201,6 +2207,7 @@ bool MYSQL_QUERY_LOG::write(THD *thd, ti { // Safety agains reopen int tmp_errno= 0; char buff[80], *end; + char utimebuff[2][20]; uint buff_len; end= buff; @@ -2230,11 +2237,14 @@ bool MYSQL_QUERY_LOG::write(THD *thd, ti if (my_b_write(&log_file, (uchar*) "\n", 1)) tmp_errno= errno; } + + sprintf(utimebuff[0], "%.6f", query_utime/1000000.0); + sprintf(utimebuff[1], "%.6f", lock_utime/1000000.0); /* For slow query log */ if (my_b_printf(&log_file, - "# Query_time: %lu Lock_time: %lu" + "# Query_time: %s Lock_time: %s" " Rows_sent: %lu Rows_examined: %lu\n", - (ulong) query_time, (ulong) lock_time, + utimebuff[0], utimebuff[1], (ulong) thd->sent_row_count, (ulong) thd->examined_row_count) == (uint) -1) tmp_errno= errno; @@ -3875,9 +3885,10 @@ int error_log_print(enum loglevel level, bool slow_log_print(THD *thd, const char *query, uint query_length, - time_t query_start_arg) -{ - return logger.slow_log_print(thd, query, query_length, query_start_arg); + time_t query_start_arg, ulonglong query_ustart_arg) +{ + return logger.slow_log_print(thd, query, query_length, query_start_arg, + query_ustart_arg); } diff -r 7d9c3a18b9f3 sql/log.h --- a/sql/log.h Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/log.h Sat Jul 07 16:59:33 2007 +0200 @@ -198,7 +198,7 @@ public: const char *sql_text, uint sql_text_len); bool write(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, uint user_host_len, - longlong query_time, longlong lock_time, bool is_command, + ulonglong query_utime, ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len); bool open_slow_log(const char *log_name) { @@ -393,8 +393,8 @@ public: virtual bool log_slow(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, - uint user_host_len, longlong query_time, - longlong lock_time, bool is_command, + uint user_host_len, ulonglong query_utime, + ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len)= 0; virtual bool log_error(enum loglevel level, const char *format, va_list args)= 0; @@ -442,8 +442,8 @@ public: virtual bool log_slow(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, - uint user_host_len, longlong query_time, - longlong lock_time, bool is_command, + uint user_host_len, ulonglong query_utime, + ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len); virtual bool log_error(enum loglevel level, const char *format, va_list args); @@ -479,8 +479,8 @@ public: virtual bool log_slow(THD *thd, time_t current_time, time_t query_start_arg, const char *user_host, - uint user_host_len, longlong query_time, - longlong lock_time, bool is_command, + uint user_host_len, ulonglong query_utime, + ulonglong lock_utime, bool is_command, const char *sql_text, uint sql_text_len); virtual bool log_error(enum loglevel level, const char *format, va_list args); @@ -564,7 +564,7 @@ public: bool error_log_print(enum loglevel level, const char *format, va_list args); bool slow_log_print(THD *thd, const char *query, uint query_length, - time_t query_start_arg); + time_t query_start_arg, ulonglong query_ustart_arg); bool general_log_print(THD *thd,enum enum_server_command command, const char *format, va_list args); diff -r 7d9c3a18b9f3 sql/log_event.cc --- a/sql/log_event.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/log_event.cc Sat Jul 07 14:39:29 2007 +0200 @@ -2074,6 +2074,7 @@ int Query_log_event::do_apply_event(RELA /* Execute the query (note that we bypass dispatch_command()) */ const char* found_semicolon= NULL; mysql_parse(thd, thd->query, thd->query_length, &found_semicolon); + log_slow_statement(thd); } else diff -r 7d9c3a18b9f3 sql/mysql_priv.h --- a/sql/mysql_priv.h Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/mysql_priv.h Sat Jul 07 16:29:50 2007 +0200 @@ -1,3 +1,4 @@ + /* Copyright (C) 2000-2003 MySQL AB This program is free software; you can redistribute it and/or modify @@ -1544,7 +1545,7 @@ int error_log_print(enum loglevel level, va_list args); bool slow_log_print(THD *thd, const char *query, uint query_length, - time_t query_start_arg); + time_t query_start_arg, ulonglong query_ustart_arg); bool general_log_print(THD *thd, enum enum_server_command command, const char *format,...); @@ -1679,6 +1680,7 @@ extern my_bool opt_secure_auth; extern my_bool opt_secure_auth; extern char* opt_secure_file_priv; extern my_bool opt_log_slow_admin_statements; +extern my_bool opt_log_slow_slave_statements; extern my_bool sp_automatic_privileges, opt_noacl; extern my_bool opt_old_style_user_limits, trust_function_creators; extern uint opt_crash_binlog_innodb; diff -r 7d9c3a18b9f3 sql/mysqld.cc --- a/sql/mysqld.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/mysqld.cc Sat Jul 07 16:16:50 2007 +0200 @@ -406,6 +406,7 @@ my_bool opt_secure_auth= 0; my_bool opt_secure_auth= 0; char* opt_secure_file_priv= 0; my_bool opt_log_slow_admin_statements= 0; +my_bool opt_log_slow_slave_statements= 0; my_bool lower_case_file_system= 0; my_bool opt_large_pages= 0; my_bool opt_myisam_use_mmap= 0; @@ -612,6 +613,8 @@ static uint thr_kill_signal; /* OS specific variables */ +ulonglong frequency= 0; + #ifdef __WIN__ #undef getpid #include @@ -3730,6 +3733,8 @@ int main(int argc, char **argv) unireg_abort(1); } } + if (!QueryPerformanceFrequency((LARGE_INTEGER *)&frequency)) + frequency= 0; #endif /* __WIN__ */ if (init_common_variables(MYSQL_CONFIG_NAME, @@ -5008,7 +5013,8 @@ enum options_mysqld OPT_MAX_SEEKS_FOR_KEY, OPT_MAX_TMP_TABLES, OPT_MAX_USER_CONNECTIONS, OPT_MAX_LENGTH_FOR_SORT_DATA, OPT_MAX_WRITE_LOCK_COUNT, OPT_BULK_INSERT_BUFFER_SIZE, - OPT_MAX_ERROR_COUNT, OPT_MULTI_RANGE_COUNT, OPT_MYISAM_DATA_POINTER_SIZE, + OPT_MAX_ERROR_COUNT, OPT_MIN_EXAMINED_ROW_LIMIT, + OPT_MULTI_RANGE_COUNT, OPT_MYISAM_DATA_POINTER_SIZE, OPT_MYISAM_BLOCK_SIZE, OPT_MYISAM_MAX_EXTRA_SORT_FILE_SIZE, OPT_MYISAM_MAX_SORT_FILE_SIZE, OPT_MYISAM_SORT_BUFFER_SIZE, OPT_MYISAM_USE_MMAP, @@ -5065,6 +5071,7 @@ enum options_mysqld OPT_TIMED_MUTEXES, OPT_OLD_STYLE_USER_LIMITS, OPT_LOG_SLOW_ADMIN_STATEMENTS, + OPT_LOG_SLOW_SLAVE_STATEMENTS, OPT_TABLE_LOCK_WAIT_TIMEOUT, OPT_PLUGIN_LOAD, OPT_PLUGIN_DIR, @@ -5375,6 +5382,11 @@ Disable with --skip-large-pages.", "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to the slow log if it is open.", (uchar**) &opt_log_slow_admin_statements, (uchar**) &opt_log_slow_admin_statements, + 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, + {"log-slow-slave-statements", OPT_LOG_SLOW_SLAVE_STATEMENTS, + "Log slow statements executed by slave thread to the slow log if it is open.", + (uchar**) &opt_log_slow_slave_statements, + (uchar**) &opt_log_slow_slave_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0}, {"log-slow-queries", OPT_SLOW_QUERY_LOG, "Log slow queries to this log file. Defaults logging to hostname-slow.log file. Must be enabled to activate other slow log options.", @@ -5966,10 +5978,10 @@ log and this option does nothing anymore 0, (GET_ULONG | GET_ASK_ADDR) , REQUIRED_ARG, 100, 1, 100, 0, 1, 0}, {"long_query_time", OPT_LONG_QUERY_TIME, - "Log all queries that have taken more than long_query_time seconds to execute to file.", + "Log all queries that have taken more than long_query_time microseconds to execute to file.", (uchar**) &global_system_variables.long_query_time, - (uchar**) &max_system_variables.long_query_time, 0, GET_ULONG, - REQUIRED_ARG, 10, 1, LONG_TIMEOUT, 0, 1, 0}, + (uchar**) &max_system_variables.long_query_time, 0, GET_ULL, + REQUIRED_ARG, 10000000, 0L, LONG_TIMEOUT * 1000000, 0, 1, 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", (uchar**) &lower_case_table_names, @@ -6067,6 +6079,11 @@ The minimum value for this variable is 4 "After this many write locks, allow some read locks to run in between.", (uchar**) &max_write_lock_count, (uchar**) &max_write_lock_count, 0, GET_ULONG, REQUIRED_ARG, ~0L, 1, ~0L, 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.", + (uchar**) &global_system_variables.min_examined_row_limit, + (uchar**) &max_system_variables.min_examined_row_limit, 0, GET_ULONG, + REQUIRED_ARG, 0, 1, ~0L, 0, 1L, 0}, {"multi_range_count", OPT_MULTI_RANGE_COUNT, "Number of key ranges to request at once.", (uchar**) &global_system_variables.multi_range_count, @@ -7771,9 +7788,9 @@ static void get_options(int *argc,char * (*argc)++; /* add back one for the progname handle_options removes */ /* no need to do this for argv as we are discarding it. */ - if ((opt_log_slow_admin_statements || opt_log_queries_not_using_indexes) && + if ((opt_log_slow_admin_statements || opt_log_slow_slave_statements || opt_log_queries_not_using_indexes) && !opt_slow_log) - sql_print_warning("options --log-slow-admin-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set"); + sql_print_warning("options --log-slow-admin-statements, --log-slow-slave-statements and --log-queries-not-using-indexes have no effect if --log-slow-queries is not set"); #if defined(HAVE_BROKEN_REALPATH) my_use_symdir=0; diff -r 7d9c3a18b9f3 sql/set_var.cc --- a/sql/set_var.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/set_var.cc Sat Jul 07 13:49:55 2007 +0200 @@ -250,7 +250,7 @@ static sys_var_bool_ptr sys_log_queries_not_using_indexes(&vars, "log_queries_not_using_indexes", &opt_log_queries_not_using_indexes); static sys_var_thd_ulong sys_log_warnings(&vars, "log_warnings", &SV::log_warnings); -static sys_var_thd_ulong sys_long_query_time(&vars, "long_query_time", +static sys_var_thd_ulonglong sys_long_query_time(&vars, "long_query_time", &SV::long_query_time); static sys_var_thd_bool sys_low_priority_updates(&vars, "low_priority_updates", &SV::low_priority_updates, @@ -315,6 +315,8 @@ static sys_var_thd_ulong sys_max_tmp_tab &SV::max_tmp_tables); static sys_var_long_ptr sys_max_write_lock_count(&vars, "max_write_lock_count", &max_write_lock_count); +static sys_var_thd_ulong sys_min_examined_row_limit(&vars, "min_examined_row_limit", + &SV::min_examined_row_limit); static sys_var_thd_ulong sys_multi_range_count(&vars, "multi_range_count", &SV::multi_range_count); static sys_var_long_ptr sys_myisam_data_pointer_size(&vars, "myisam_data_pointer_size", diff -r 7d9c3a18b9f3 sql/slave.cc --- a/sql/slave.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/slave.cc Sat Jul 07 14:34:35 2007 +0200 @@ -1398,6 +1398,8 @@ static int init_slave_thread(THD* thd, S thd->variables.max_allowed_packet= global_system_variables.max_allowed_packet + MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */ thd->slave_thread = 1; + if (opt_log_slow_slave_statements) + thd->enable_slow_log= TRUE; set_slave_thread_options(thd); thd->client_capabilities = CLIENT_LOCAL_FILES; pthread_mutex_lock(&LOCK_thread_count); diff -r 7d9c3a18b9f3 sql/sql_class.cc --- a/sql/sql_class.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/sql_class.cc Sat Jul 07 23:55:48 2007 +0200 @@ -378,6 +378,8 @@ THD::THD() lex->current_select= 0; start_time=(time_t) 0; time_after_lock=(time_t) 0; + start_utime= 0L; + utime_after_lock= 0L; current_linfo = 0; slave_thread = 0; bzero(&variables, sizeof(variables)); diff -r 7d9c3a18b9f3 sql/sql_class.h --- a/sql/sql_class.h Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/sql_class.h Sun Jul 08 01:08:09 2007 +0200 @@ -47,6 +47,7 @@ extern char internal_table_name[2]; 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) @@ -244,13 +245,14 @@ struct system_variables 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; @@ -1051,6 +1053,7 @@ public: */ const char *where; time_t start_time,time_after_lock,user_time; + ulonglong start_utime,utime_after_lock; time_t connect_time,thr_create_time; // track down slow pthread_create thr_lock_type update_lock_default; Delayed_insert *di; @@ -1561,10 +1564,22 @@ public: 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 void set_time(time_t t) { time_after_lock=start_time=user_time=t; } - inline void lock_time() { time(&time_after_lock); } + inline ulonglong query_ustart() { return start_utime; } + inline void set_time() + { + if (user_time) + start_time=time_after_lock=user_time; + else + time_after_lock=time(&start_time); + utime_after_lock= my_utime(&start_utime, frequency); + } + inline void end_time() { time(&start_time); my_utime(&start_utime, frequency); } + inline void set_time(time_t t) + { + time_after_lock=start_time=user_time=t; + utime_after_lock= my_utime(&start_utime, frequency); + } + inline void lock_time() { time(&time_after_lock); my_utime(&utime_after_lock, frequency); } inline ulonglong found_rows(void) { return limit_found_rows; diff -r 7d9c3a18b9f3 sql/sql_parse.cc --- a/sql/sql_parse.cc Sat Jul 07 11:05:37 2007 +0200 +++ b/sql/sql_parse.cc Sun Jul 08 01:24:29 2007 +0200 @@ -1298,6 +1298,7 @@ void log_slow_statement(THD *thd) void log_slow_statement(THD *thd) { time_t start_of_query; + ulonglong ustart_of_query; DBUG_ENTER("log_slow_statement"); /* @@ -1309,24 +1310,28 @@ void log_slow_statement(THD *thd) DBUG_VOID_RETURN; // Don't set time for sub stmt start_of_query= thd->start_time; + ustart_of_query= thd->start_utime; thd->end_time(); // Set start time /* Do not log administrative statements unless the appropriate option is set; do not log into slow log if reading from backup. */ - if (thd->enable_slow_log && !thd->user_time) + if (thd->enable_slow_log && + ((thd->slave_thread && opt_log_slow_slave_statements) || !thd->user_time)) { thd->proc_info="logging slow query"; - 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)) && - (specialflag & SPECIAL_LOG_QUERIES_NOT_USING_INDEXES))) + if (((thd->start_utime - thd->utime_after_lock > + thd->variables.long_query_time) || + ((thd->server_status & + (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && + (specialflag & SPECIAL_LOG_QUERIES_NOT_USING_INDEXES))) && + thd->examined_row_count >= thd->variables.min_examined_row_limit) { thd->status_var.long_query_count++; - slow_log_print(thd, thd->query, thd->query_length, start_of_query); + slow_log_print(thd, thd->query, thd->query_length, start_of_query, + ustart_of_query); } } DBUG_VOID_RETURN;