#!!! notice !!!
# Any small change to this file in the main branch
# should be done or reviewed by the maintainer!
-diff -ruN a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp
---- a/include/mysql/plugin_audit.h.pp 2011-04-09 18:48:05.000000000 +0400
-+++ b/include/mysql/plugin_audit.h.pp 2011-04-09 18:48:50.000000000 +0400
-@@ -178,6 +178,16 @@
+--- a/include/mysql/plugin_audit.h.pp
++++ b/include/mysql/plugin_audit.h.pp
+@@ -185,6 +185,16 @@
char *thd_security_context(void* thd, char *buffer, unsigned int length,
unsigned int max_query_len);
void thd_inc_row_count(void* thd);
int mysql_tmpfile(const char *prefix);
int thd_killed(const void* thd);
unsigned long thd_get_thread_id(const void* thd);
-diff -ruN a/include/mysql/plugin_auth.h.pp b/include/mysql/plugin_auth.h.pp
---- a/include/mysql/plugin_auth.h.pp 2011-04-09 18:48:05.000000000 +0400
-+++ b/include/mysql/plugin_auth.h.pp 2011-04-09 18:48:50.000000000 +0400
-@@ -178,6 +178,16 @@
+--- a/include/mysql/plugin_auth.h.pp
++++ b/include/mysql/plugin_auth.h.pp
+@@ -185,6 +185,16 @@
char *thd_security_context(void* thd, char *buffer, unsigned int length,
unsigned int max_query_len);
void thd_inc_row_count(void* thd);
int mysql_tmpfile(const char *prefix);
int thd_killed(const void* thd);
unsigned long thd_get_thread_id(const void* thd);
-diff -ruN a/include/mysql/plugin_ftparser.h.pp b/include/mysql/plugin_ftparser.h.pp
---- a/include/mysql/plugin_ftparser.h.pp 2011-04-09 18:48:05.000000000 +0400
-+++ b/include/mysql/plugin_ftparser.h.pp 2011-04-09 18:48:50.000000000 +0400
-@@ -131,6 +131,16 @@
+--- a/include/mysql/plugin_ftparser.h.pp
++++ b/include/mysql/plugin_ftparser.h.pp
+@@ -138,6 +138,16 @@
char *thd_security_context(void* thd, char *buffer, unsigned int length,
unsigned int max_query_len);
void thd_inc_row_count(void* thd);
int mysql_tmpfile(const char *prefix);
int thd_killed(const void* thd);
unsigned long thd_get_thread_id(const void* thd);
-diff -ruN a/include/mysql/plugin.h b/include/mysql/plugin.h
---- a/include/mysql/plugin.h 2011-04-09 18:48:05.000000000 +0400
-+++ b/include/mysql/plugin.h 2011-04-09 18:48:50.000000000 +0400
+--- a/include/mysql/plugin.h
++++ b/include/mysql/plugin.h
@@ -536,6 +536,17 @@
/* Increments the row counter, see THD::row_count */
void thd_inc_row_count(MYSQL_THD thd);
/**
Create a temporary file.
-diff -ruN /dev/null b/patch_info/slow_extended.info
---- /dev/null 1970-01-01 00:00:00.000000000 +0000
-+++ b/patch_info/slow_extended.info 2011-04-09 18:48:50.000000000 +0400
+--- /dev/null
++++ b/patch_info/slow_extended.info
@@ -0,0 +1,25 @@
+File=slow_extended.patch
+Name=Extended statistics in slow.log (not InnoDB part)
+6) Change variable types (system/command-line)
+2011-01
+Patch profiling_slow.patch was merged
-diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh
---- a/scripts/mysqldumpslow.sh 2011-04-09 18:48:05.000000000 +0400
-+++ b/scripts/mysqldumpslow.sh 2011-04-09 18:48:50.000000000 +0400
-@@ -101,8 +101,8 @@
+--- a/scripts/mysqldumpslow.sh
++++ b/scripts/mysqldumpslow.sh
+@@ -102,8 +102,8 @@
s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
$t -= $l unless $opt{l};
# remove fluff that mysqld writes to log when it (re)starts:
-diff -ruN a/sql/event_scheduler.cc b/sql/event_scheduler.cc
---- a/sql/event_scheduler.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/event_scheduler.cc 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/event_scheduler.cc
++++ b/sql/event_scheduler.cc
@@ -195,6 +195,7 @@
thd->client_capabilities|= CLIENT_MULTI_RESULTS;
mysql_mutex_lock(&LOCK_thread_count);
mysql_mutex_unlock(&LOCK_thread_count);
/*
-diff -ruN a/sql/filesort.cc b/sql/filesort.cc
---- a/sql/filesort.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/filesort.cc 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/filesort.cc
++++ b/sql/filesort.cc
@@ -195,6 +195,7 @@
{
status_var_increment(thd->status_var.filesort_scan_count);
if (param->not_killable)
{
killed= ¬_killable;
-diff -ruN a/sql/log.cc b/sql/log.cc
---- a/sql/log.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/log.cc 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/log.cc
++++ b/sql/log.cc
@@ -715,11 +715,13 @@
*/
if (thd->db && strcmp(thd->db, db))
{ // Database changed
if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
-diff -ruN a/sql/log.h b/sql/log.h
---- a/sql/log.h 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/log.h 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/log.h
++++ b/sql/log.h
@@ -242,7 +242,7 @@
uint user_host_len, int thread_id,
const char *command_type, uint command_type_len,
time_t query_start_arg, const char *user_host,
uint user_host_len, ulonglong query_utime,
ulonglong lock_utime, bool is_command,
-diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc
---- a/sql/mysqld.cc 2011-04-09 18:48:20.000000000 +0400
-+++ b/sql/mysqld.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -420,6 +420,10 @@
+--- a/sql/mysqld.cc
++++ b/sql/mysqld.cc
+@@ -421,6 +421,10 @@
char* opt_secure_file_priv;
my_bool opt_log_slow_admin_statements= 0;
my_bool opt_log_slow_slave_statements= 0;
+my_bool opt_log_slow_sp_statements= 0;
+my_bool opt_slow_query_log_timestamp_always= 0;
+ulonglong opt_slow_query_log_use_global_control= 0;
-+ulonglong opt_slow_query_log_timestamp_precision= 0;
++ulong opt_slow_query_log_timestamp_precision= 0;
my_bool lower_case_file_system= 0;
my_bool opt_large_pages= 0;
my_bool opt_super_large_pages= 0;
-@@ -5839,10 +5843,10 @@
+@@ -5896,10 +5900,10 @@
"Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to "
"the slow log if it is open.", &opt_log_slow_admin_statements,
&opt_log_slow_admin_statements, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
{"log-slow-queries", OPT_SLOW_QUERY_LOG,
"Log slow queries to a table or log file. Defaults logging to table "
"mysql.slow_log or hostname-slow.log if --log-output=file is used. "
-@@ -7231,6 +7235,10 @@
+@@ -7288,6 +7292,10 @@
C_MODE_END
/**
Get server options from the command line,
and perform related server initializations.
-@@ -7372,6 +7380,8 @@
+@@ -7437,6 +7445,8 @@
global_system_variables.long_query_time= (ulonglong)
(global_system_variables.long_query_time_double * 1e6);
if (opt_short_log_format)
opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT;
-diff -ruN a/sql/mysqld.h b/sql/mysqld.h
---- a/sql/mysqld.h 2011-04-09 18:48:17.000000000 +0400
-+++ b/sql/mysqld.h 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/mysqld.h
++++ b/sql/mysqld.h
@@ -116,6 +116,10 @@
extern char* opt_secure_backup_file_priv;
extern size_t opt_secure_backup_file_priv_len;
+extern my_bool opt_log_slow_sp_statements;
+extern my_bool opt_slow_query_log_timestamp_always;
+extern ulonglong opt_slow_query_log_use_global_control;
-+extern ulonglong opt_slow_query_log_timestamp_precision;
++extern ulong opt_slow_query_log_timestamp_precision;
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 -ruN a/sql/slave.cc b/sql/slave.cc
---- a/sql/slave.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/slave.cc 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/slave.cc
++++ b/sql/slave.cc
@@ -2038,6 +2038,7 @@
+ MAX_LOG_EVENT_HEADER; /* note, incr over the global not session var */
thd->slave_thread = 1;
set_slave_thread_options(thd);
thd->client_capabilities = CLIENT_LOCAL_FILES;
mysql_mutex_lock(&LOCK_thread_count);
-diff -ruN a/sql/sp_head.cc b/sql/sp_head.cc
---- a/sql/sp_head.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/sp_head.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -2150,7 +2150,7 @@
+--- a/sql/sp_head.cc
++++ b/sql/sp_head.cc
+@@ -2152,7 +2152,7 @@
DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length,
m_name.str));
}
{
DBUG_PRINT("info", ("Disabling slow log for the execution"));
save_enable_slow_log= true;
-diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc
---- a/sql/sql_cache.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/sql_cache.cc 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/sql_cache.cc
++++ b/sql/sql_cache.cc
@@ -1756,6 +1756,7 @@
response, we can't handle it anyway.
*/
MYSQL_QUERY_CACHE_MISS(thd->query());
DBUG_RETURN(0); // Query was not cached
}
-diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc
---- a/sql/sql_class.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/sql_class.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -368,6 +368,37 @@
+--- a/sql/sql_class.cc
++++ b/sql/sql_class.cc
+@@ -616,6 +616,37 @@
thd->warning_info->inc_current_row_for_warning();
}
/**
Dumps a text description of a thread, its security context
-@@ -662,6 +693,7 @@
+@@ -912,6 +943,7 @@
*cond_hdl= NULL;
return FALSE;
}
for (Internal_error_handler *error_handler= m_internal_handler;
error_handler;
-@@ -3390,6 +3422,12 @@
+@@ -3656,6 +3688,12 @@
first_successful_insert_id_in_prev_stmt;
backup->first_successful_insert_id_in_cur_stmt=
first_successful_insert_id_in_cur_stmt;
if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
!is_current_stmt_binlog_format_row())
-@@ -3410,6 +3448,14 @@
+@@ -3676,6 +3714,14 @@
cuted_fields= 0;
transaction.savepoints= 0;
first_successful_insert_id_in_cur_stmt= 0;
}
-@@ -3472,6 +3518,12 @@
+@@ -3738,6 +3784,12 @@
*/
examined_row_count+= backup->examined_row_count;
cuted_fields+= backup->cuted_fields;
DBUG_VOID_RETURN;
}
-diff -ruN a/sql/sql_class.h b/sql/sql_class.h
---- a/sql/sql_class.h 2011-04-09 18:48:19.000000000 +0400
-+++ b/sql/sql_class.h 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/sql_class.h
++++ b/sql/sql_class.h
@@ -60,6 +60,33 @@
enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
SLAVE_EXEC_MODE_IDEMPOTENT,
SLAVE_EXEC_MODE_LAST_BIT};
-@@ -508,6 +535,17 @@
+@@ -508,6 +535,21 @@
my_bool sysdate_is_now;
++#ifndef DBUG_OFF
++ ulonglong query_exec_time;
++ double query_exec_time_double;
++#endif
+ ulong log_slow_rate_limit;
+ ulonglong log_slow_filter;
+ ulonglong log_slow_verbosity;
double long_query_time_double;
} SV;
-@@ -1140,6 +1178,14 @@
+@@ -1140,6 +1182,14 @@
uint in_sub_stmt;
bool enable_slow_log;
bool last_insert_id_used;
SAVEPOINT *savepoints;
enum enum_check_fields count_cuted_fields;
};
-@@ -1575,6 +1621,26 @@
+@@ -1588,6 +1638,26 @@
thr_lock_type update_lock_default;
Delayed_insert *di;
/* <> 0 if we are inside of trigger or stored function. */
uint in_sub_stmt;
-diff -ruN a/sql/sql_connect.cc b/sql/sql_connect.cc
---- a/sql/sql_connect.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/sql_connect.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -764,6 +764,15 @@
-
- prepare_new_connection_state(thd);
+--- a/sql/sql_connect.cc
++++ b/sql/sql_connect.cc
+@@ -721,6 +721,15 @@
+ MYSQL_CONNECTION_START(thd->thread_id, &thd->security_ctx->priv_user[0],
+ (char *) thd->security_ctx->host_or_ip);
+ /*
+ If rate limiting of slow log writes is enabled, decide whether to log this
+ (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
+ thd->write_to_slow_log= TRUE;
+
- while (!net->error && net->vio != 0 &&
- !(thd->killed == THD::KILL_CONNECTION))
- {
-diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc
---- a/sql/sql_parse.cc 2011-04-09 18:48:20.000000000 +0400
-+++ b/sql/sql_parse.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -1430,7 +1430,6 @@
+ prepare_new_connection_state(thd);
+ return FALSE;
+ }
+--- a/sql/sql_parse.cc
++++ b/sql/sql_parse.cc
+@@ -114,6 +114,7 @@
+
+ static bool execute_sqlcom_select(THD *thd, TABLE_LIST *all_tables);
+ static void sql_kill(THD *thd, ulong id, bool only_kill_query);
++static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime);
+
+ const char *any_db="*any*"; // Special symbol for check_access
+
+@@ -1430,6 +1431,60 @@
DBUG_RETURN(error);
}
--
++/**
++ Calculate execution time for the current query.
++
++ For debug builds, check the session value of query_exec_time
++ and if it is not zero, return it instead of the actual execution time.
++
++ SET queries are ignored so that statements changing query_exec_time are not
++ affected by themselves.
++
++ @param thd thread handle
++ @param lex current relative time in microseconds
++
++ @return time in microseconds from utime_after_lock
++*/
++
++static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
++{
++ ulonglong res;
++#ifndef DBUG_OFF
++ if (thd->variables.query_exec_time != 0)
++ res= thd->lex->sql_command != SQLCOM_SET_OPTION ?
++ thd->variables.query_exec_time : 0;
++ else
++#endif
++
++ res= cur_utime - thd->utime_after_lock;
++
++ if (res > thd->variables.long_query_time)
++ thd->server_status|= SERVER_QUERY_WAS_SLOW;
++ else
++ thd->server_status&= ~SERVER_QUERY_WAS_SLOW;
++
++ return res;
++}
++
++
++static inline void copy_global_to_session(THD *thd, ulong flag,
++ const ulong *val)
++{
++ my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
++ if (opt_slow_query_log_use_global_control & (1ULL << flag))
++ *(ulong *)((char *) &thd->variables + offset) = *val;
++}
++
++
++static inline void copy_global_to_session(THD *thd, ulong flag,
++ const ulonglong *val)
++{
++ my_ptrdiff_t offset = ((char *)val - (char *)&global_system_variables);
++ if (opt_slow_query_log_use_global_control & (1ULL << flag))
++ *(ulonglong *)((char *) &thd->variables + offset) = *val;
++}
++
++
+
void log_slow_statement(THD *thd)
{
- DBUG_ENTER("log_slow_statement");
-@@ -1443,6 +1442,42 @@
+@@ -1443,13 +1498,48 @@
if (unlikely(thd->in_sub_stmt))
DBUG_VOID_RETURN; // Don't set time for sub stmt
+ (thd->query_plan_flags & QPLAN_QC))))
+ DBUG_VOID_RETURN;
+
++ ulonglong end_utime_of_query= thd->current_utime();
++ ulonglong query_exec_time= get_query_exec_time(thd, end_utime_of_query);
++
+ /*
+ Low long_query_time value most likely means user is debugging stuff and even
+ though some thread's queries are not supposed to be logged b/c of the rate
+ to make an exception and write to slow log anyway.
+ */
+
-+ ulonglong end_utime_of_query= thd->current_utime();
-+#define USE_GLOBAL_UPDATE(variable_name,enum_value_name) \
-+ if (opt_slow_query_log_use_global_control & (ULL(1) << enum_value_name)) \
-+ { \
-+ thd->variables. variable_name= \
-+ global_system_variables. variable_name; \
-+ }
-+ USE_GLOBAL_UPDATE(log_slow_filter,SLOG_UG_LOG_SLOW_FILTER);
-+ USE_GLOBAL_UPDATE(log_slow_rate_limit,SLOG_UG_LOG_SLOW_RATE_LIMIT);
-+ USE_GLOBAL_UPDATE(log_slow_verbosity,SLOG_UG_LOG_SLOW_VERBOSITY);
-+ USE_GLOBAL_UPDATE(long_query_time,SLOG_UG_LONG_QUERY_TIME);
-+ USE_GLOBAL_UPDATE(long_query_time_double,SLOG_UG_LONG_QUERY_TIME);
-+ USE_GLOBAL_UPDATE(min_examined_row_limit,SLOG_UG_MIN_EXAMINED_ROW_LIMIT);
-+#undef USE_GLOBAL_UPDATE
++ system_variables const &g= global_system_variables;
++ copy_global_to_session(thd, SLOG_UG_LOG_SLOW_FILTER,
++ &g.log_slow_filter);
++ copy_global_to_session(thd, SLOG_UG_LOG_SLOW_RATE_LIMIT,
++ &g.log_slow_rate_limit);
++ copy_global_to_session(thd, SLOG_UG_LOG_SLOW_VERBOSITY,
++ &g.log_slow_verbosity);
++ copy_global_to_session(thd, SLOG_UG_LONG_QUERY_TIME,
++ &g.long_query_time);
++ copy_global_to_session(thd, SLOG_UG_MIN_EXAMINED_ROW_LIMIT,
++ &g.min_examined_row_limit);
+
+ /* Do not log this thread's queries due to rate limiting. */
+ if (thd->write_to_slow_log != TRUE
+ && (thd->variables.long_query_time >= 1000000
-+ || (ulong) (end_utime_of_query - thd->utime_after_lock) < 1000000))
++ || (ulong) query_exec_time < 1000000))
+ DBUG_VOID_RETURN;
+
+
/*
Do not log administrative statements unless the appropriate option is
set.
-@@ -1818,6 +1853,9 @@
+ */
+ if (thd->enable_slow_log)
+ {
+- ulonglong end_utime_of_query= thd->current_utime();
+ thd_proc_info(thd, "logging slow query");
+
+ if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
+@@ -1879,6 +1969,9 @@
context.resolve_in_table_list_only(select_lex->
table_list.first);
/*
Reset warning count for each query that uses tables
A better approach would be to reset this for any commands
-@@ -5248,6 +5286,21 @@
+@@ -5297,6 +5390,21 @@
thd->rand_used= 0;
thd->sent_row_count= thd->examined_row_count= 0;
thd->reset_current_stmt_binlog_format_row();
thd->binlog_unsafe_warning_flags= 0;
-diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc
---- a/sql/sql_select.cc 2011-04-09 18:48:17.000000000 +0400
-+++ b/sql/sql_select.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -6898,7 +6898,10 @@
+--- a/sql/sql_select.cc
++++ b/sql/sql_select.cc
+@@ -6902,7 +6902,10 @@
{
join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
if (statistics)
}
}
else
-@@ -6912,7 +6915,10 @@
+@@ -6916,7 +6919,10 @@
{
join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
if (statistics)
}
}
if (!table->no_keyread)
-@@ -10243,6 +10249,7 @@
+@@ -10264,6 +10270,7 @@
(ulong) rows_limit,test(group)));
status_var_increment(thd->status_var.created_tmp_tables);
if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES))
temp_pool_slot = bitmap_lock_set_next(&temp_pool);
-@@ -11141,6 +11148,7 @@
+@@ -11162,6 +11169,7 @@
goto err;
}
status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
share->db_record_offset= 1;
DBUG_RETURN(0);
err:
-@@ -11159,6 +11167,14 @@
+@@ -11180,6 +11188,14 @@
save_proc_info=thd->proc_info;
thd_proc_info(thd, "removing tmp table");
// Release latches since this can take a long time
ha_release_temporary_latches(thd);
-diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc
---- a/sql/sql_show.cc 2011-04-09 18:48:20.000000000 +0400
-+++ b/sql/sql_show.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -1943,8 +1943,17 @@
+--- a/sql/sql_show.cc
++++ b/sql/sql_show.cc
+@@ -1950,8 +1950,17 @@
table->field[4]->store(command_name[tmp->command].str,
command_name[tmp->command].length, cs);
/* MYSQL_TIME */
/* STATE */
if ((val= thread_state_info(tmp)))
{
-diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc
---- a/sql/sys_vars.cc 2011-04-09 18:48:19.000000000 +0400
-+++ b/sql/sys_vars.cc 2011-04-09 18:48:50.000000000 +0400
-@@ -2862,6 +2862,117 @@
+--- a/sql/sys_vars.cc
++++ b/sql/sys_vars.cc
+@@ -972,6 +972,29 @@
+ NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
+ ON_UPDATE(update_cached_long_query_time));
+
++#ifndef DBUG_OFF
++static bool update_cached_query_exec_time(sys_var *self, THD *thd,
++ enum_var_type type)
++{
++ if (type == OPT_SESSION)
++ thd->variables.query_exec_time=
++ double2ulonglong(thd->variables.query_exec_time_double * 1e6);
++ else
++ global_system_variables.query_exec_time=
++ double2ulonglong(global_system_variables.query_exec_time_double * 1e6);
++ return false;
++}
++
++static Sys_var_double Sys_query_exec_time(
++ "query_exec_time",
++ "Pretend queries take this many seconds. When 0 (the default) use the "
++ "actual execution time. Used only for debugging.",
++ SESSION_VAR(query_exec_time_double),
++ NO_CMD_LINE, VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(0),
++ NO_MUTEX_GUARD, IN_BINLOG, ON_CHECK(0),
++ ON_UPDATE(update_cached_query_exec_time));
++#endif
++
+ static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type)
+ {
+ if (type == OPT_SESSION)
+@@ -2898,6 +2921,117 @@
DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
ON_UPDATE(fix_log_state));
/* Synonym of "slow_query_log" for consistency with SHOW VARIABLES output */
static Sys_var_mybool Sys_log_slow(
"log_slow_queries",
-diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc
---- a/sql/sql_profile.cc 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/sql_profile.cc 2011-04-09 18:48:50.000000000 +0400
+--- a/sql/sql_profile.cc
++++ b/sql/sql_profile.cc
@@ -243,7 +243,8 @@
{
time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
/**
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 -ruN a/sql/sql_profile.h b/sql/sql_profile.h
---- a/sql/sql_profile.h 2011-04-09 18:48:05.000000000 +0400
-+++ b/sql/sql_profile.h 2011-04-09 18:48:50.000000000 +0400
+@@ -600,6 +728,8 @@
+
+ #ifdef HAVE_GETRUSAGE
+
++ if (enabled_getrusage())
++ {
+ my_decimal cpu_utime_decimal, cpu_stime_decimal;
+
+ double2my_decimal(E_DEC_FATAL_ERROR,
+@@ -687,6 +817,7 @@
+ 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
+--- a/sql/sql_profile.h
++++ b/sql/sql_profile.h
@@ -164,11 +164,15 @@
*/
class PROF_MEASUREMENT
};
# endif /* HAVE_PROFILING */
+--- /dev/null
++++ b/mysql-test/include/log_grep.inc
+@@ -0,0 +1,17 @@
++--disable_query_log
++--echo [log_grep.inc] file: $log_file pattern: $grep_pattern
++perl;
++ $log_file= $ENV{'log_file'};
++ $log_file_full_path= $ENV{'log_file_full_path'};
++ $grep_pattern= $ENV{'grep_pattern'};
++
++ open(FILE, "$log_file_full_path")
++ or die("Cannot open file $log_file_full_path: $!\n");
++
++ $lines = 0;
++ while(<FILE>) {
++ $lines++ if (/$grep_pattern/);
++ }
++ close(FILE);
++ print "[log_grep.inc] lines: $lines\n";
++EOF
+--- /dev/null
++++ b/mysql-test/include/log_start.inc
+@@ -0,0 +1,16 @@
++--disable_query_log
++--let log_file_full_path = $MYSQLTEST_VARDIR/$log_file
++SET @slow_query_log_old=@@slow_query_log;
++SET @slow_query_log_file_old= @@slow_query_log_file;
++SET GLOBAL slow_query_log=OFF;
++perl;
++ $log_file_full_path= $ENV{'log_file_full_path'};
++ unlink $log_file_full_path;
++ open(FILE, '>', $log_file_full_path)
++ or die "Cannot create log file $log_file_full_path, reason: $!";
++ close(FILE);
++EOF
++--echo [log_start.inc] $log_file
++EVAL SET GLOBAL slow_query_log_file="$log_file_full_path";
++SET GLOBAL slow_query_log=ON;
++--enable_query_log
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/include/log_stop.inc
+@@ -0,0 +1,7 @@
++--disable_query_log
++FLUSH LOGS;
++SET GLOBAL slow_query_log=OFF;
++--echo [log_stop.inc] $log_file
++SET GLOBAL slow_query_log_file= @slow_query_log_file_old;
++SET GLOBAL slow_query_log= @slow_query_log_old;
++--enable_query_log
+--- /dev/null
++++ b/mysql-test/r/percona_bug643149.result
+@@ -0,0 +1,21 @@
++SET @old_slow_query_log_file=@@global.slow_query_log_file;
++SET GLOBAL slow_query_log=on;
++SET LOCAL log_slow_verbosity='profiling';
++SET LOCAL long_query_time=0;
++SET GLOBAL slow_query_log_file='MYSQLTEST_VARDIR/percona_bug643149_slow.log';;
++SELECT 1;
++1
++1
++# User@Host: root[root] @ localhost []
++# Thread_id: X Schema: test Last_errno: X Killed: X
++# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X
++# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X
++# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X
++# Profile_total: X.X Profile_total_cpu: X.X
++# User@Host: root[root] @ localhost []
++# Thread_id: X Schema: test Last_errno: X Killed: X
++# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X
++# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X
++# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_closing_tables: X.X Profile_closing_tables_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X
++# Profile_total: X.X Profile_total_cpu: X.X
++SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_filter-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_filter';
++Variable_name Value
++log_slow_filter full_join
++SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
++Variable_name Value
++log_slow_filter full_join
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_filter.result
+@@ -0,0 +1,15 @@
++CREATE TABLE t(id INT PRIMARY KEY);
++INSERT INTO t VALUES(1);
++INSERT INTO t VALUES(2);
++INSERT INTO t VALUES(3);
++SET long_query_time=1;
++SET log_slow_filter=full_join;
++[log_start.inc] percona.slow_extended.log_slow_filter
++SET query_exec_time = 1.1;
++SELECT * FROM t AS t1, t AS t2;
++SET query_exec_time = default;
++[log_stop.inc] percona.slow_extended.log_slow_filter
++SET log_slow_filter=default;
++SET long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.log_slow_filter pattern: Query_time
++[log_grep.inc] lines: 1
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_slave_statements';
++Variable_name Value
++log_slow_slave_statements ON
++SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
++Variable_name Value
++log_slow_slave_statements ON
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements-innodb.result
+@@ -0,0 +1,18 @@
++include/master-slave.inc
++[connection master]
++DROP TABLE IF EXISTS t;
++CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
++INSERT INTO t VALUES
++(1,"aaaaabbbbbcccccdddddeeeeefffff"),
++(2,"aaaaabbbbbcccccdddddeeeeefffff"),
++(3,"aaaaabbbbbcccccdddddeeeeefffff"),
++(4,"aaaaabbbbbcccccdddddeeeeefffff"),
++(5,"aaaaabbbbbcccccdddddeeeeefffff");
++INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
++INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
++[log_start.inc] percona.slow_extended.log_slow_slave_statements-innodb
++INSERT INTO t SELECT t.id,t.data from t;
++[log_stop.inc] percona.slow_extended.log_slow_slave_statements-innodb
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements-innodb pattern: InnoDB_IO_r_ops
++[log_grep.inc] lines: 1
++include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements.result
+@@ -0,0 +1,44 @@
++include/master-slave.inc
++[connection master]
++DROP TABLE IF EXISTS t;
++CREATE TABLE t(id INT);
++[log_start.inc] percona.slow_extended.log_slow_slave_statements
++LINE 1
++LOG_SLOW_SLAVE_STATAMENTS is OFF
++LOG_SLOW_SLAVE_STATEMENTS=ON
++LOG_SLOW_SLAVE_STATAMENTS is ON
++LINE 2
++include/restart_slave.inc
++LOG_SLOW_SLAVE_STATAMENTS is ON
++LINE 3
++LOG_SLOW_SLAVE_STATAMENTS is ON
++LOG_SLOW_SLAVE_STATEMENTS=OFF
++LOG_SLOW_SLAVE_STATAMENTS is OFF
++LINE 4
++include/restart_slave.inc
++LOG_SLOW_SLAVE_STATAMENTS is OFF
++LINE 5
++LOG_SLOW_SLAVE_STATAMENTS is OFF
++LOG_SLOW_SLAVE_STATEMENTS=ON
++LOG_SLOW_SLAVE_STATAMENTS is ON
++LINE 6
++include/restart_slave.inc
++LOG_SLOW_SLAVE_STATAMENTS is ON
++LINE 7
++[log_stop.inc] percona.slow_extended.log_slow_slave_statements
++SET GLOBAL log_slow_slave_statements=default;
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(1\)
++[log_grep.inc] lines: 0
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(2\)
++[log_grep.inc] lines: 0
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(3\)
++[log_grep.inc] lines: 1
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(4\)
++[log_grep.inc] lines: 0
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(5\)
++[log_grep.inc] lines: 0
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(6\)
++[log_grep.inc] lines: 0
++[log_grep.inc] file: percona.slow_extended.log_slow_slave_statements pattern: INSERT INTO t VALUES \(7\)
++[log_grep.inc] lines: 1
++include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_sp_statements-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_sp_statements';
++Variable_name Value
++log_slow_sp_statements ON
++SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
++Variable_name Value
++log_slow_sp_statements ON
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_sp_statements.result
+@@ -0,0 +1,24 @@
++SET long_query_time=1;
++SET GLOBAL log_slow_sp_statements=ON;
++SET SESSION query_exec_time=0.1;
++[log_start.inc] percona.slow_extended.log_slow_sp_statements
++CREATE PROCEDURE test_f()
++BEGIN
++SET SESSION query_exec_time=1.1; SELECT 1;
++SET SESSION query_exec_time=2.1; SELECT 1;
++SET SESSION query_exec_time=3.1; SELECT 1;
++SET SESSION query_exec_time=0.1;
++END^
++CALL test_f();
++1
++1
++1
++1
++1
++1
++[log_stop.inc] percona.slow_extended.log_slow_sp_statements
++SET SESSION query_exec_time=default;
++SET GLOBAL log_slow_sp_statements=default;
++SET long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.log_slow_sp_statements pattern: Query_time
++[log_grep.inc] lines: 3
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_verbosity-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'log_slow_verbosity';
++Variable_name Value
++log_slow_verbosity microtime,query_plan,innodb
++SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
++Variable_name Value
++log_slow_verbosity microtime,query_plan,innodb
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_verbosity.result
+@@ -0,0 +1,16 @@
++SET SESSION long_query_time=1;
++[log_start.inc] percona.slow_extended.log_slow_verbosity
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SET SESSION log_slow_verbosity=innodb;
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++[log_stop.inc] percona.slow_extended.log_slow_verbosity
++SET log_slow_verbosity=default;
++SET long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.log_slow_verbosity pattern: No InnoDB statistics available for this query
++[log_grep.inc] lines: 1
+--- /dev/null
++++ b/mysql-test/r/percona_long_query_time.result
+@@ -0,0 +1,33 @@
++SET long_query_time=2;
++[log_start.inc] percona.slow_extended.long_query_time
++SET SESSION query_exec_time=1.1;
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=3.1;
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=5.1;
++SELECT 1;
++1
++1
++SET long_query_time=4;
++SET SESSION query_exec_time=1.1;
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=3.1;
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=5.1;
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++SET long_query_time=2;
++[log_stop.inc] percona.slow_extended.long_query_time
++SET long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.long_query_time pattern: Query_time
++[log_grep.inc] lines: 3
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_always-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
++Variable_name Value
++slow_query_log_timestamp_always ON
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
++Variable_name Value
++slow_query_log_timestamp_always ON
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_always.result
+@@ -0,0 +1,41 @@
++SET long_query_time=2;
++SET GLOBAL slow_query_log_timestamp_always=ON;
++[log_start.inc] percona.slow_extended.slow_query_log_timestamp_always
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SELECT 1;
++1
++1
++SELECT 1;
++1
++1
++SET GLOBAL slow_query_log_timestamp_always=OFF;
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SELECT 1;
++1
++1
++SELECT 1;
++1
++1
++SET GLOBAL slow_query_log_timestamp_always=ON;
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SELECT 1;
++1
++1
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_always
++SET GLOBAL slow_query_log_timestamp_always=default;
++SET long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_always pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
++[log_grep.inc] lines: 6
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_precision-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
++Variable_name Value
++slow_query_log_timestamp_precision microsecond
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
++Variable_name Value
++slow_query_log_timestamp_precision microsecond
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_timestamp_precision.result
+@@ -0,0 +1,18 @@
++SET long_query_time=2;
++[log_start.inc] percona.slow_extended.slow_query_log_timestamp_precision
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SET GLOBAL slow_query_log_timestamp_precision='microsecond';
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++[log_stop.inc] percona.slow_extended.slow_query_log_timestamp_precision
++SET GLOBAL slow_query_log_timestamp_precision=default;
++SET long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
++[log_grep.inc] lines: 1
++[log_grep.inc] file: percona.slow_extended.slow_query_log_timestamp_precision pattern: # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
++[log_grep.inc] lines: 2
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_use_global_control.result
+@@ -0,0 +1,18 @@
++SET GLOBAL long_query_time=1;
++[log_start.inc] percona.slow_extended.slow_query_log_use_global_control
++SET SESSION query_exec_time=1.1;
++SELECT 1;
++1
++1
++SET GLOBAL log_slow_verbosity=innodb;
++SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++[log_stop.inc] percona.slow_extended.slow_query_log_use_global_control
++SET GLOBAL slow_query_log_use_global_control=default;
++SET GLOBAL log_slow_verbosity=default;
++SET GLOBAL long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.slow_query_log_use_global_control pattern: No InnoDB statistics available for this query
++[log_grep.inc] lines: 1
+--- /dev/null
++++ b/mysql-test/t/percona_bug643149.test
+@@ -0,0 +1,49 @@
++#
++# This test suffers from server
++# Bug#38124 "general_log_file" variable silently unset when using expression
++# In short:
++# SET GLOBAL general_log_file = @<whatever>
++# SET GLOBAL slow_query_log = @<whatever>
++# cause that the value of these server system variables is set to default
++# instead of the assigned values. There comes no error message or warning.
++# If this bug is fixed please
++# 1. try this test with "let $fixed_bug38124 = 0;"
++# 2. remove all workarounds if 1. was successful.
++--source include/have_profiling.inc
++let $fixed_bug38124 = 0;
++
++SET @old_slow_query_log_file=@@global.slow_query_log_file;
++SET GLOBAL slow_query_log=on;
++SET LOCAL log_slow_verbosity='profiling';
++SET LOCAL long_query_time=0;
++
++let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log;
++--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
++--eval SET GLOBAL slow_query_log_file='$slogfile';
++
++SELECT 1;
++
++perl;
++ $slogfile= $ENV{'slogfile'};
++
++ open(FILE, "$slogfile") or
++ die("Unable to read slow query log file $slogfile: $!\n");
++ while(<FILE>) {
++ next if (!/^#/);
++ next if (/^# Time:/);
++ s/[0-9]+/X/g;
++ print;
++ }
++
++ close(FILE);
++EOF
++
++SET GLOBAL slow_query_log_file=@old_slow_query_log_file;
++
++if(!$fixed_bug38124)
++{
++ --disable_query_log
++ let $my_var = `SELECT @old_slow_query_log_file`;
++ eval SET @@global.slow_query_log_file = '$my_var';
++ --enable_query_log
++}
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_filter-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_filter=full_join
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_filter-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'log_slow_filter';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_filter';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_filter.test
+@@ -0,0 +1,26 @@
++--source include/have_debug.inc
++
++CREATE TABLE t(id INT PRIMARY KEY);
++INSERT INTO t VALUES(1);
++INSERT INTO t VALUES(2);
++INSERT INTO t VALUES(3);
++
++SET long_query_time=1;
++SET log_slow_filter=full_join;
++--let log_file=percona.slow_extended.log_slow_filter
++--source include/log_start.inc
++
++SET query_exec_time = 1.1;
++--disable_result_log
++SELECT * FROM t AS t1, t AS t2;
++--enable_result_log
++SET query_exec_time = default;
++
++--source include/log_stop.inc
++SET log_slow_filter=default;
++SET long_query_time=default;
++
++--let grep_pattern = Query_time
++--source include/log_grep.inc
++
++DROP TABLE t;
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_slave_statements
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-cl.test
+@@ -0,0 +1,3 @@
++SHOW VARIABLES LIKE 'log_slow_slave_statements';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_slave_statements';
++
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt
+@@ -0,0 +1 @@
++--long_query_time=0 --log_slow_slave_statements --log_slow_verbosity=innodb
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-innodb.test
+@@ -0,0 +1,42 @@
++--source include/have_binlog_format_statement.inc
++--source include/master-slave.inc
++--source include/have_innodb.inc
++--let log_file=percona.slow_extended.log_slow_slave_statements-innodb
++
++connection master;
++-- disable_warnings
++DROP TABLE IF EXISTS t;
++-- enable_warnings
++
++CREATE TABLE t(id INT,data CHAR(30)) ENGINE=InnoDB;
++INSERT INTO t VALUES
++(1,"aaaaabbbbbcccccdddddeeeeefffff"),
++(2,"aaaaabbbbbcccccdddddeeeeefffff"),
++(3,"aaaaabbbbbcccccdddddeeeeefffff"),
++(4,"aaaaabbbbbcccccdddddeeeeefffff"),
++(5,"aaaaabbbbbcccccdddddeeeeefffff");
++INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
++INSERT INTO t SELECT t2.id,t2.data from t as t1, t as t2;
++sync_slave_with_master;
++
++connection slave;
++--source include/log_start.inc
++
++connection master;
++INSERT INTO t SELECT t.id,t.data from t;
++sync_slave_with_master;
++
++connection slave;
++--source include/log_stop.inc
++
++--enable_query_log
++--enable_result_log
++
++--let grep_pattern = InnoDB_IO_r_ops
++--source include/log_grep.inc
++
++connection master;
++DROP TABLE t;
++sync_slave_with_master;
++
++--source include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements-slave.opt
+@@ -0,0 +1 @@
++--long_query_time=0
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_slave_statements.test
+@@ -0,0 +1,117 @@
++-- source include/have_binlog_format_statement.inc
++-- source include/master-slave.inc
++--let log_file=percona.slow_extended.log_slow_slave_statements
++--let show=SELECT Variable_value FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name LIKE 'log_slow_slave_statements';
++
++connection master;
++-- disable_warnings
++DROP TABLE IF EXISTS t;
++-- enable_warnings
++
++CREATE TABLE t(id INT);
++sync_slave_with_master;
++
++connection slave;
++--source include/log_start.inc
++
++--disable_query_log
++--disable_result_log
++
++--echo LINE 1
++connection master;
++INSERT INTO t VALUES (1);
++sync_slave_with_master;
++
++connection slave;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++--echo LOG_SLOW_SLAVE_STATEMENTS=ON
++SET GLOBAL log_slow_slave_statements=ON;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++
++--echo LINE 2
++connection master;
++INSERT INTO t VALUES (2);
++sync_slave_with_master;
++
++--source include/restart_slave_sql.inc
++
++connection slave;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++
++--echo LINE 3
++connection master;
++INSERT INTO t VALUES (3);
++sync_slave_with_master;
++
++connection slave;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++--echo LOG_SLOW_SLAVE_STATEMENTS=OFF
++SET GLOBAL log_slow_slave_statements=OFF;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++
++--echo LINE 4
++connection master;
++INSERT INTO t VALUES (4);
++sync_slave_with_master;
++
++--source include/restart_slave_sql.inc
++
++connection slave;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++
++--echo LINE 5
++connection master;
++INSERT INTO t VALUES (5);
++sync_slave_with_master;
++
++connection slave;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++--echo LOG_SLOW_SLAVE_STATEMENTS=ON
++SET GLOBAL log_slow_slave_statements=ON;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++
++--echo LINE 6
++connection master;
++INSERT INTO t VALUES (6);
++sync_slave_with_master;
++
++--source include/restart_slave_sql.inc
++
++connection slave;
++--let value=`$show`
++--echo LOG_SLOW_SLAVE_STATAMENTS is $value
++
++--echo LINE 7
++connection master;
++INSERT INTO t VALUES (7);
++sync_slave_with_master;
++
++--enable_query_log
++--enable_result_log
++
++connection slave;
++--source include/log_stop.inc
++SET GLOBAL log_slow_slave_statements=default;
++
++connection slave;
++--let i=1
++while($i < 8)
++{
++--let grep_pattern= INSERT INTO t VALUES \($i\)
++--source include/log_grep.inc
++ inc $i;
++}
++
++connection master;
++DROP TABLE t;
++sync_slave_with_master;
++
++--source include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_sp_statements-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_sp_statements
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_sp_statements-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'log_slow_sp_statements';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_sp_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_sp_statements.test
+@@ -0,0 +1,29 @@
++--source include/have_debug.inc
++
++SET long_query_time=1;
++SET GLOBAL log_slow_sp_statements=ON;
++SET SESSION query_exec_time=0.1;
++--let log_file=percona.slow_extended.log_slow_sp_statements
++--source include/log_start.inc
++
++delimiter ^;
++CREATE PROCEDURE test_f()
++BEGIN
++ SET SESSION query_exec_time=1.1; SELECT 1;
++ SET SESSION query_exec_time=2.1; SELECT 1;
++ SET SESSION query_exec_time=3.1; SELECT 1;
++ SET SESSION query_exec_time=0.1;
++END^
++delimiter ;^
++
++CALL test_f();
++
++--source include/log_stop.inc
++SET SESSION query_exec_time=default;
++SET GLOBAL log_slow_sp_statements=default;
++SET long_query_time=default;
++
++--let grep_pattern = Query_time
++--source include/log_grep.inc
++
++DROP PROCEDURE test_f;
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_verbosity-cl-master.opt
+@@ -0,0 +1 @@
++--log_slow_verbosity="full"
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_verbosity-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'log_slow_verbosity';
++SHOW GLOBAL VARIABLES LIKE 'log_slow_verbosity';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_verbosity.test
+@@ -0,0 +1,19 @@
++--source include/have_innodb.inc
++--source include/have_debug.inc
++
++SET SESSION long_query_time=1;
++--let log_file=percona.slow_extended.log_slow_verbosity
++--source include/log_start.inc
++
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++SET SESSION log_slow_verbosity=innodb;
++SELECT 1;
++SET SESSION query_exec_time=default;
++
++--source include/log_stop.inc
++SET log_slow_verbosity=default;
++SET long_query_time=default;
++
++--let grep_pattern = No InnoDB statistics available for this query
++--source include/log_grep.inc
+--- /dev/null
++++ b/mysql-test/t/percona_long_query_time.test
+@@ -0,0 +1,25 @@
++--source include/have_debug.inc
++
++SET long_query_time=2;
++--let log_file=percona.slow_extended.long_query_time
++--source include/log_start.inc
++
++SET SESSION query_exec_time=1.1; SELECT 1;
++SET SESSION query_exec_time=3.1; SELECT 1;
++SET SESSION query_exec_time=5.1; SELECT 1;
++
++SET long_query_time=4;
++
++SET SESSION query_exec_time=1.1; SELECT 1;
++SET SESSION query_exec_time=3.1; SELECT 1;
++SET SESSION query_exec_time=5.1; SELECT 1;
++
++SET SESSION query_exec_time=default;
++
++SET long_query_time=2;
++
++--source include/log_stop.inc
++SET long_query_time=default;
++
++--let grep_pattern = Query_time
++--source include/log_grep.inc
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_timestamp_always
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_always-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_always';
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_always';
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_always.test
+@@ -0,0 +1,34 @@
++--source include/have_debug.inc
++
++SET long_query_time=2;
++SET GLOBAL slow_query_log_timestamp_always=ON;
++--let log_file=percona.slow_extended.slow_query_log_timestamp_always
++--source include/log_start.inc
++
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++SELECT 1;
++SELECT 1;
++
++SET GLOBAL slow_query_log_timestamp_always=OFF;
++
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++SELECT 1;
++SELECT 1;
++
++SET GLOBAL slow_query_log_timestamp_always=ON;
++
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++SELECT 1;
++SELECT 1;
++
++SET SESSION query_exec_time=default;
++
++--source include/log_stop.inc
++SET GLOBAL slow_query_log_timestamp_always=default;
++SET long_query_time=default;
++
++--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
++--source include/log_grep.inc
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_timestamp_precision='microsecond'
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'slow_query_log_timestamp_precision';
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_timestamp_precision';
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_timestamp_always
+\ No newline at end of file
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_timestamp_precision.test
+@@ -0,0 +1,25 @@
++--source include/have_debug.inc
++
++SET long_query_time=2;
++--let log_file=percona.slow_extended.slow_query_log_timestamp_precision
++--source include/log_start.inc
++
++SET SESSION query_exec_time=2.1;
++
++SELECT 1;
++
++SET GLOBAL slow_query_log_timestamp_precision='microsecond';
++
++SELECT 1;
++
++SET SESSION query_exec_time=default;
++
++--source include/log_stop.inc
++SET GLOBAL slow_query_log_timestamp_precision=default;
++SET long_query_time=default;
++
++--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
++--source include/log_grep.inc
++
++--let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+
++--source include/log_grep.inc
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_use_global_control.test
+@@ -0,0 +1,28 @@
++--source include/have_debug.inc
++--source include/have_innodb.inc
++
++SET GLOBAL long_query_time=1;
++
++--let log_file=percona.slow_extended.slow_query_log_use_global_control
++--source include/log_start.inc
++
++SET SESSION query_exec_time=1.1;
++SELECT 1;
++
++SET GLOBAL log_slow_verbosity=innodb;
++SET GLOBAL slow_query_log_use_global_control="log_slow_verbosity,long_query_time";
++
++SELECT 1;
++
++SET SESSION query_exec_time=default;
++
++--source include/log_stop.inc
++
++
++SET GLOBAL slow_query_log_use_global_control=default;
++SET GLOBAL log_slow_verbosity=default;
++SET GLOBAL long_query_time=default;
++
++--let grep_pattern = No InnoDB statistics available for this query
++--source include/log_grep.inc
++
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_use_global_control-cl.result
+@@ -0,0 +1,6 @@
++SHOW VARIABLES LIKE 'slow_query_log_use_global_control';
++Variable_name Value
++slow_query_log_use_global_control log_slow_verbosity,long_query_time
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control';
++Variable_name Value
++slow_query_log_use_global_control log_slow_verbosity,long_query_time
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl-master.opt
+@@ -0,0 +1 @@
++--slow_query_log_use_global_control="log_slow_verbosity,long_query_time"
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_use_global_control-cl.test
+@@ -0,0 +1,2 @@
++SHOW VARIABLES LIKE 'slow_query_log_use_global_control';
++SHOW GLOBAL VARIABLES LIKE 'slow_query_log_use_global_control';
+--- /dev/null
++++ b/mysql-test/r/percona_min_examined_row_limit.result
+@@ -0,0 +1,34 @@
++drop table if exists t;
++create table t(id INT PRIMARY KEY);
++insert into t values(1);
++insert into t values(2);
++insert into t values(3);
++SET GLOBAL long_query_time=2;
++SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit';
++[log_start.inc] percona.slow_extended.min_examined_row_limit
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++1
++1
++SET GLOBAL min_examined_row_limit=5;
++select * from t as t1, t as t2;
++id id
++1 1
++2 1
++3 1
++1 2
++2 2
++3 2
++1 3
++2 3
++3 3
++SELECT 1;
++1
++1
++SET SESSION query_exec_time=default;
++[log_stop.inc] percona.slow_extended.min_examined_row_limit
++SET GLOBAL min_examined_row_limit=default;
++SET GLOBAL slow_query_log_use_global_control=default;
++SET GLOBAL long_query_time=default;
++[log_grep.inc] file: percona.slow_extended.min_examined_row_limit pattern: Query_time
++[log_grep.inc] lines: 1
+--- /dev/null
++++ b/mysql-test/t/percona_min_examined_row_limit.test
+@@ -0,0 +1,35 @@
++--source include/have_debug.inc
++
++--disable_warnings
++drop table if exists t;
++--enable_warnings
++
++create table t(id INT PRIMARY KEY);
++insert into t values(1);
++insert into t values(2);
++insert into t values(3);
++
++SET GLOBAL long_query_time=2;
++SET GLOBAL slow_query_log_use_global_control='long_query_time,min_examined_row_limit';
++--let log_file=percona.slow_extended.min_examined_row_limit
++--source include/log_start.inc
++
++SET SESSION query_exec_time=2.1;
++SELECT 1;
++
++SET GLOBAL min_examined_row_limit=5;
++
++select * from t as t1, t as t2;
++SELECT 1;
++
++SET SESSION query_exec_time=default;
++
++--source include/log_stop.inc
++SET GLOBAL min_examined_row_limit=default;
++SET GLOBAL slow_query_log_use_global_control=default;
++SET GLOBAL long_query_time=default;
++
++--let grep_pattern = Query_time
++--source include/log_grep.inc
++
++DROP TABLE t;
+--- a/sql/log_event.cc
++++ b/sql/log_event.cc
+@@ -2380,6 +2380,14 @@
+ start+= host.length;
+ }
+ }
++#ifndef DBUG_OFF
++ if (thd && thd->variables.query_exec_time > 0)
++ {
++ *start++= Q_QUERY_EXEC_TIME;
++ int8store(start, thd->variables.query_exec_time);
++ start+= 8;
++ }
++#endif
+ /*
+ NOTE: When adding new status vars, please don't forget to update
+ the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update the function
+@@ -2866,6 +2874,17 @@
+ data_written= master_data_written= uint4korr(pos);
+ pos+= 4;
+ break;
++#if !defined(DBUG_OFF) && !defined(MYSQL_CLIENT)
++ case Q_QUERY_EXEC_TIME:
++ {
++ THD *thd= current_thd;
++ CHECK_SPACE(pos, end, 8);
++ if (thd)
++ thd->variables.query_exec_time= uint8korr(pos);
++ pos+= 8;
++ break;
++ }
++#endif
+ case Q_INVOKER:
+ {
+ CHECK_SPACE(pos, end, 1);
+--- a/sql/log_event.h
++++ b/sql/log_event.h
+@@ -342,6 +342,10 @@
+
+ #define Q_INVOKER 11
+
++#ifndef DBUG_OFF
++#define Q_QUERY_EXEC_TIME 250
++#endif
++
+ /* Intvar event post-header */
+
+ /* Intvar event data */
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/query_exec_time_basic.result
+@@ -0,0 +1,2 @@
++SET GLOBAL query_exec_time=default;
++SET SESSION query_exec_time=default;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/query_exec_time_basic.test
+@@ -0,0 +1,4 @@
++--source include/have_debug.inc
++
++SET GLOBAL query_exec_time=default;
++SET SESSION query_exec_time=default;
projects / packages / mysql.git / blobdiff