#!!! 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
+@@ -186,6 +186,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
+@@ -186,6 +186,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
+@@ -139,6 +139,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
-@@ -536,6 +536,17 @@
+--- a/include/mysql/plugin.h
++++ b/include/mysql/plugin.h
+@@ -545,6 +545,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);
thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
-+ thd->write_to_slow_log = TRUE;
++ thd->write_to_slow_log= true;
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
-@@ -195,6 +195,7 @@
+--- a/sql/filesort.cc
++++ b/sql/filesort.cc
+@@ -193,6 +193,7 @@
{
status_var_increment(thd->status_var.filesort_scan_count);
}
#ifdef CAN_TRUST_RANGE
if (select && select->quick && select->quick->records > 0L)
{
-@@ -260,6 +261,7 @@
- }
- else
- {
+@@ -261,6 +262,7 @@
+ /* filesort cannot handle zero-length records during merge. */
+ DBUG_ASSERT(param.sort_length != 0);
+
+ thd->query_plan_flags|= QPLAN_FILESORT_DISK;
if (table_sort.buffpek && table_sort.buffpek_len < maxbuffer)
{
my_free(table_sort.buffpek);
-@@ -1219,6 +1221,7 @@
+@@ -1209,6 +1211,7 @@
DBUG_ENTER("merge_buffers");
status_var_increment(current_thd->status_var.filesort_merge_passes);
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 @@
*/
user_host, user_host_len,
query_utime, lock_utime, is_command,
sql_text, sql_text_len);
-@@ -1216,7 +1218,7 @@
+@@ -1200,8 +1202,6 @@
+
+ if (*slow_log_handler_list)
+ {
+- time_t current_time;
+-
+ /* do not log slow queries from replication threads */
+ if (thd->slave_thread && !opt_log_slow_slave_statements)
+ return 0;
+@@ -1216,16 +1216,29 @@
/* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
sctx->priv_user ? sctx->priv_user : "", "[",
sctx->host ? sctx->host : "", " [",
sctx->ip ? sctx->ip : "", "]", NullS) -
user_host_buff);
-@@ -1224,8 +1226,22 @@
- current_time= my_time_possible_from_micro(current_utime);
+
+- current_time= my_time_possible_from_micro(current_utime);
if (thd->start_utime)
{
- query_utime= (current_utime - thd->start_utime);
}
else
{
-@@ -1239,8 +1255,20 @@
- query_length= command_name[thd->command].length;
+@@ -1240,7 +1253,7 @@
}
-+ if (!query_length)
-+ {
-+ thd->sent_row_count= thd->examined_row_count= 0;
-+ thd->sent_row_count= 0;
-+ thd->bytes_sent_old= thd->status_var.bytes_sent;
-+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
-+ thd->tmp_tables_size= 0;
-+ thd->innodb_was_used= FALSE;
-+ thd->query_plan_flags= QPLAN_NONE;
-+ thd->query_plan_fsort_passes= 0;
-+ }
-+
for (current_handler= slow_log_handler_list; *current_handler ;)
- error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
+ error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
user_host_buff, user_host_len,
query_utime, lock_utime, is_command,
query, query_length) || error;
-@@ -2656,12 +2684,13 @@
+@@ -2656,12 +2669,13 @@
TRUE - error occured
*/
bool error= 0;
DBUG_ENTER("MYSQL_QUERY_LOG::write");
-@@ -2683,17 +2712,28 @@
+@@ -2683,17 +2697,28 @@
if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
{
/* Note that my_b_write() assumes it knows the length for this */
if (my_b_write(&log_file, (uchar*) buff, buff_len))
-@@ -2711,12 +2751,69 @@
+@@ -2710,13 +2735,71 @@
+ /* For slow query log */
sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
++ DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno));
if (my_b_printf(&log_file,
- "# Query_time: %s Lock_time: %s"
- " Rows_sent: %lu Rows_examined: %lu\n",
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,
const char *user_host, uint user_host_len,
ulonglong query_utime, ulonglong lock_utime, bool is_command,
const char *sql_text, uint sql_text_len);
-@@ -515,7 +515,7 @@
+@@ -517,7 +517,7 @@
virtual bool init()= 0;
virtual void cleanup()= 0;
time_t query_start_arg, const char *user_host,
uint user_host_len, ulonglong query_utime,
ulonglong lock_utime, bool is_command,
-@@ -544,7 +544,7 @@
+@@ -546,7 +546,7 @@
virtual bool init();
virtual void cleanup();
time_t query_start_arg, const char *user_host,
uint user_host_len, ulonglong query_utime,
ulonglong lock_utime, bool is_command,
-@@ -576,7 +576,7 @@
+@@ -578,7 +578,7 @@
virtual bool init();
virtual void cleanup();
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
-@@ -416,6 +416,10 @@
+--- a/sql/mysqld.cc
++++ b/sql/mysqld.cc
+@@ -421,6 +421,11 @@
char* opt_secure_file_priv;
my_bool opt_log_slow_admin_statements= 0;
my_bool opt_log_slow_slave_statements= 0;
+my_bool opt_slow_query_log_timestamp_always= 0;
+ulonglong opt_slow_query_log_use_global_control= 0;
+ulong opt_slow_query_log_timestamp_precision= 0;
++ulong opt_slow_query_log_rate_type= 0;
my_bool lower_case_file_system= 0;
my_bool opt_large_pages= 0;
my_bool opt_super_large_pages= 0;
-@@ -5835,10 +5839,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},
+@@ -5892,14 +5897,10 @@
+ "Don't log extra information to update and slow-query logs.",
+ &opt_short_log_format, &opt_short_log_format,
+ 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
+- {"log-slow-admin-statements", 0,
+- "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-slave-statements", 0,
+ /*{"log-slow-slave-statements", 0,
"Log slow statements executed by slave thread to the slow log if it is open.",
{"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. "
-@@ -7227,6 +7231,10 @@
+@@ -7288,6 +7289,10 @@
C_MODE_END
/**
Get server options from the command line,
and perform related server initializations.
-@@ -7376,6 +7384,8 @@
+@@ -7437,6 +7442,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
-@@ -116,6 +116,10 @@
+--- a/sql/mysqld.h
++++ b/sql/mysqld.h
+@@ -116,6 +116,11 @@
extern char* opt_secure_backup_file_priv;
extern size_t opt_secure_backup_file_priv_len;
extern my_bool opt_log_slow_admin_statements, opt_log_slow_slave_statements;
+extern my_bool opt_slow_query_log_timestamp_always;
+extern ulonglong opt_slow_query_log_use_global_control;
+extern ulong opt_slow_query_log_timestamp_precision;
++extern ulong opt_slow_query_log_rate_type;
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
-@@ -2151,7 +2151,7 @@
+--- a/sql/sp_head.cc
++++ b/sql/sp_head.cc
+@@ -2164,7 +2164,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
-@@ -1756,6 +1756,7 @@
+--- a/sql/sql_cache.cc
++++ b/sql/sql_cache.cc
+@@ -1780,6 +1780,7 @@
response, we can't handle it anyway.
*/
(void) trans_commit_stmt(thd);
if (!thd->stmt_da->is_set())
thd->stmt_da->disable_status();
-@@ -1766,6 +1767,7 @@
+@@ -1790,6 +1791,7 @@
err_unlock:
unlock();
err:
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
-@@ -367,6 +367,37 @@
+--- a/sql/sql_class.cc
++++ b/sql/sql_class.cc
+@@ -616,6 +616,37 @@
thd->warning_info->inc_current_row_for_warning();
}
+extern "C"
+void increment_thd_innodb_stats(THD* thd,
-+ unsigned long long trx_id,
-+ long io_reads,
-+ long long io_read,
-+ long io_reads_wait_timer,
-+ long lock_que_wait_timer,
-+ long que_wait_timer,
-+ long page_access)
++ unsigned long long trx_id,
++ long io_reads,
++ long long io_read,
++ long io_reads_wait_timer,
++ long lock_que_wait_timer,
++ long que_wait_timer,
++ long page_access)
+{
-+ thd->innodb_was_used = TRUE;
-+ thd->innodb_trx_id = trx_id;
-+ thd->innodb_io_reads += io_reads;
-+ thd->innodb_io_read += io_read;
-+ thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
-+ thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
-+ thd->innodb_innodb_que_wait_timer += que_wait_timer;
-+ thd->innodb_page_access += page_access;
++ thd->innodb_was_used= TRUE;
++ thd->innodb_trx_id= trx_id;
++ thd->innodb_io_reads+= io_reads;
++ thd->innodb_io_read+= io_read;
++ thd->innodb_io_reads_wait_timer+= io_reads_wait_timer;
++ thd->innodb_lock_que_wait_timer+= lock_que_wait_timer;
++ thd->innodb_innodb_que_wait_timer+= que_wait_timer;
++ thd->innodb_page_access+= page_access;
+}
+
+extern "C"
/**
Dumps a text description of a thread, its security context
-@@ -661,6 +692,7 @@
- *cond_hdl= NULL;
- return FALSE;
- }
+@@ -942,6 +973,8 @@
+ const char* msg,
+ MYSQL_ERROR ** cond_hdl)
+ {
+ last_errno= sql_errno;
++
+ if (!m_internal_handler)
+ {
+ *cond_hdl= NULL;
+@@ -1236,6 +1269,8 @@
+ /* Initialize the Debug Sync Facility. See debug_sync.cc. */
+ debug_sync_init_thread(this);
+ #endif /* defined(ENABLED_DEBUG_SYNC) */
++
++ clear_slow_extended();
+ }
+
- for (Internal_error_handler *error_handler= m_internal_handler;
- error_handler;
-@@ -3385,6 +3417,12 @@
+@@ -3687,8 +3722,6 @@
+ backup->in_sub_stmt= in_sub_stmt;
+ backup->enable_slow_log= enable_slow_log;
+ backup->limit_found_rows= limit_found_rows;
+- backup->examined_row_count= examined_row_count;
+- backup->sent_row_count= sent_row_count;
+ backup->cuted_fields= cuted_fields;
+ backup->client_capabilities= client_capabilities;
+ backup->savepoints= transaction.savepoints;
+@@ -3696,6 +3729,7 @@
first_successful_insert_id_in_prev_stmt;
backup->first_successful_insert_id_in_cur_stmt=
first_successful_insert_id_in_cur_stmt;
-+ backup->innodb_io_reads= innodb_io_reads;
-+ backup->innodb_io_read= innodb_io_read;
-+ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
-+ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
-+ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
-+ backup->innodb_page_access= innodb_page_access;
++ reset_sub_statement_state_slow_extended(backup);
if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
!is_current_stmt_binlog_format_row())
-@@ -3405,6 +3443,14 @@
+@@ -3711,13 +3745,74 @@
+ /* Disable result sets */
+ client_capabilities &= ~CLIENT_MULTI_RESULTS;
+ in_sub_stmt|= new_state;
+- examined_row_count= 0;
+- sent_row_count= 0;
cuted_fields= 0;
transaction.savepoints= 0;
first_successful_insert_id_in_cur_stmt= 0;
-+ last_errno= 0;
-+ innodb_trx_id= 0;
-+ innodb_io_reads= 0;
-+ innodb_io_read= 0;
-+ innodb_io_reads_wait_timer= 0;
-+ innodb_lock_que_wait_timer= 0;
-+ innodb_innodb_que_wait_timer= 0;
-+ innodb_page_access= 0;
}
++void THD::clear_slow_extended()
++{
++ DBUG_ENTER("THD::clear_slow_extended");
++ sent_row_count= 0;
++ examined_row_count= 0;
++ bytes_sent_old= status_var.bytes_sent;
++ tmp_tables_used= 0;
++ tmp_tables_disk_used= 0;
++ tmp_tables_size= 0;
++ innodb_was_used= FALSE;
++ innodb_trx_id= 0;
++ innodb_io_reads= 0;
++ innodb_io_read= 0;
++ innodb_io_reads_wait_timer= 0;
++ innodb_lock_que_wait_timer= 0;
++ innodb_innodb_que_wait_timer= 0;
++ innodb_page_access= 0;
++ query_plan_flags= QPLAN_NONE;
++ query_plan_fsort_passes= 0;
++ last_errno= 0;
++ DBUG_VOID_RETURN;
++}
++
++void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup)
++{
++ DBUG_ENTER("THD::reset_sub_statement_state_slow_extended");
++ backup->sent_row_count= sent_row_count;
++ backup->examined_row_count= examined_row_count;
++ backup->tmp_tables_used= tmp_tables_used;
++ backup->tmp_tables_disk_used= tmp_tables_disk_used;
++ backup->tmp_tables_size= tmp_tables_size;
++ backup->innodb_was_used= innodb_was_used;
++ backup->innodb_io_reads= innodb_io_reads;
++ backup->innodb_io_read= innodb_io_read;
++ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
++ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
++ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
++ backup->innodb_page_access= innodb_page_access;
++ backup->query_plan_flags= query_plan_flags;
++ backup->query_plan_fsort_passes= query_plan_fsort_passes;
++ clear_slow_extended();
++ DBUG_VOID_RETURN;
++}
++
++void THD::restore_sub_statement_state_slow_extended(const Sub_statement_state *backup)
++{
++ DBUG_ENTER("THD::restore_sub_statement_state_slow_extended");
++ sent_row_count= backup->sent_row_count;
++ examined_row_count+= backup->examined_row_count;
++ tmp_tables_used+= backup->tmp_tables_used;
++ tmp_tables_disk_used+= backup->tmp_tables_disk_used;
++ tmp_tables_size+= backup->tmp_tables_size;
++ innodb_was_used= (innodb_was_used || backup->innodb_was_used);
++ innodb_io_reads+= backup->innodb_io_reads;
++ innodb_io_read+= backup->innodb_io_read;
++ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
++ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
++ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
++ innodb_page_access+= backup->innodb_page_access;
++ query_plan_flags|= backup->query_plan_flags;
++ query_plan_fsort_passes+= backup->query_plan_fsort_passes;
++ DBUG_VOID_RETURN;
++}
-@@ -3467,6 +3513,12 @@
+ void THD::restore_sub_statement_state(Sub_statement_state *backup)
+ {
+@@ -3758,7 +3853,6 @@
+ first_successful_insert_id_in_cur_stmt=
+ backup->first_successful_insert_id_in_cur_stmt;
+ limit_found_rows= backup->limit_found_rows;
+- sent_row_count= backup->sent_row_count;
+ client_capabilities= backup->client_capabilities;
+ /*
+ If we've left sub-statement mode, reset the fatal error flag.
+@@ -3776,8 +3870,8 @@
+ The following is added to the old values as we are interested in the
+ total complexity of the query
*/
- examined_row_count+= backup->examined_row_count;
+- examined_row_count+= backup->examined_row_count;
cuted_fields+= backup->cuted_fields;
-+ innodb_io_reads+= backup->innodb_io_reads;
-+ innodb_io_read+= backup->innodb_io_read;
-+ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
-+ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
-+ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
-+ innodb_page_access+= backup->innodb_page_access;
++ restore_sub_statement_state_slow_extended(backup);
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
-@@ -60,6 +60,33 @@
+@@ -3802,7 +3896,7 @@
+ {
+ mysql_mutex_lock(&LOCK_thd_data);
+ set_query_inner(query_arg, query_length_arg, cs);
+- query_id= new_query_id;
++ do_set_query_id(new_query_id);
+ mysql_mutex_unlock(&LOCK_thd_data);
+ }
+
+@@ -3811,9 +3905,25 @@
+ void THD::set_query_id(query_id_t new_query_id)
+ {
+ mysql_mutex_lock(&LOCK_thd_data);
+- query_id= new_query_id;
++ do_set_query_id(new_query_id);
+ mysql_mutex_unlock(&LOCK_thd_data);
+ }
++void THD::do_set_query_id(query_id_t new_query_id)
++{
++#ifndef DBUG_OFF
++ if (variables.query_exec_id != 0 &&
++ lex->sql_command != SQLCOM_SET_OPTION)
++ {
++ new_query_id= variables.query_exec_id;
++ }
++#endif /* DBUG_OFF */
++ query_id= new_query_id;
++ if (opt_slow_query_log_rate_type == SLOG_RT_QUERY)
++ {
++ const ulong& limit= variables.log_slow_rate_limit;
++ write_to_slow_log= limit == 0 || (query_id % limit) == 0;
++ }
++}
+
+ /** Assign a new value to thd->mysys_var. */
+ void THD::set_mysys_var(struct st_my_thread_var *new_mysys_var)
+--- a/sql/sql_class.h
++++ b/sql/sql_class.h
+@@ -60,6 +60,36 @@
enum enum_duplicates { DUP_ERROR, DUP_REPLACE, DUP_UPDATE };
enum enum_delay_key_write { DELAY_KEY_WRITE_NONE, DELAY_KEY_WRITE_ON,
DELAY_KEY_WRITE_ALL };
+enum enum_slow_query_log_timestamp_precision {
+ SLOG_SECOND, SLOG_MICROSECOND
+};
++enum enum_slow_query_log_rate_type {
++ SLOG_RT_SESSION, SLOG_RT_QUERY
++};
+#define QPLAN_NONE 0
+#define QPLAN_QC 1 << 0
+#define QPLAN_QC_NO 1 << 1
enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
SLAVE_EXEC_MODE_IDEMPOTENT,
SLAVE_EXEC_MODE_LAST_BIT};
-@@ -508,6 +535,17 @@
+@@ -508,6 +538,22 @@
my_bool sysdate_is_now;
++#ifndef DBUG_OFF
++ ulonglong query_exec_time;
++ double query_exec_time_double;
++ ulong query_exec_id;
++#endif
+ ulong log_slow_rate_limit;
+ ulonglong log_slow_filter;
+ ulonglong log_slow_verbosity;
double long_query_time_double;
} SV;
-@@ -1135,6 +1173,14 @@
+@@ -1140,6 +1186,24 @@
uint in_sub_stmt;
bool enable_slow_log;
bool last_insert_id_used;
+
++ /*** Following variables used in slow_extended.patch ***/
++ ulong tmp_tables_used;
++ ulong tmp_tables_disk_used;
++ ulonglong tmp_tables_size;
++
++ bool innodb_was_used;
+ ulong innodb_io_reads;
+ ulonglong innodb_io_read;
+ ulong innodb_io_reads_wait_timer;
+ ulong innodb_lock_que_wait_timer;
+ ulong innodb_innodb_que_wait_timer;
+ ulong innodb_page_access;
++
++ ulong query_plan_flags;
++ ulong query_plan_fsort_passes;
++ /*** The variables above used in slow_extended.patch ***/
+
SAVEPOINT *savepoints;
enum enum_check_fields count_cuted_fields;
};
-@@ -1583,6 +1629,26 @@
+@@ -1588,6 +1652,71 @@
thr_lock_type update_lock_default;
Delayed_insert *di;
++ /*** Following variables used in slow_extended.patch ***/
++ /*
++ Variable write_to_slow_log:
++ 1) initialized in
++ * sql_connect.cc (log_slow_rate_limit support)
++ * slave.cc (log_slow_slave_statements support)
++ 2) The variable is initialized on the thread startup and remains
++ constant afterwards. This will change when
++ LP #712396 ("log_slow_slave_statements not work on replication
++ threads without RESTART") is implemented.
++ 3) An implementation of LP #688646 ("Make query sampling possible by query") should use it.
++ */
+ bool write_to_slow_log;
-+
++ /*
++ Variable bytes_send_old saves value of thd->status_var.bytes_sent
++ before query execution.
++ */
+ ulonglong bytes_sent_old;
++ /*
++ Variables tmp_tables_*** collect statistics about usage of temporary tables
++ */
+ ulong tmp_tables_used;
+ ulong tmp_tables_disk_used;
+ ulonglong tmp_tables_size;
++ /*
++ Variable innodb_was_used shows used or not InnoDB engine in current query.
++ */
+ bool innodb_was_used;
++ /*
++ Following Variables innodb_*** (is |should be) different from
++ default values only if (innodb_was_used==TRUE)
++ */
+ ulonglong innodb_trx_id;
+ ulong innodb_io_reads;
+ ulonglong innodb_io_read;
+ ulong innodb_innodb_que_wait_timer;
+ ulong innodb_page_access;
+
++ /*
++ Variable query_plan_flags collects information about query plan entites
++ used on query execution.
++ */
+ ulong query_plan_flags;
++ /*
++ Variable query_plan_fsort_passes collects information about file sort passes
++ acquired during query execution.
++ */
+ ulong query_plan_fsort_passes;
-+
++ /*
++ Query can generate several errors/warnings during execution
++ (see THD::handle_condition comment in sql_class.h)
++ Variable last_errno contains the last error/warning acquired during
++ query execution.
++ */
+ uint last_errno;
++ /*** The variables above used in slow_extended.patch ***/
++
++ /*** Following methods used in slow_extended.patch ***/
++ void clear_slow_extended();
++ void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
++ void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup);
++ /*** The methods above used in slow_extended.patch ***/
+
/* <> 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,4 +764,13 @@
-
-+ /*
-+ If rate limiting of slow log writes is enabled, decide whether to log this
-+ new thread's queries or not. Uses extremely simple algorithm. :)
-+ */
-+ thd->write_to_slow_log= FALSE;
-+ if (thd->variables.log_slow_rate_limit <= 1 ||
-+ (thd->thread_id % thd->variables.log_slow_rate_limit) == 0)
-+ thd->write_to_slow_log= TRUE;
-+
- prepare_new_connection_state(thd);
-
- while (!net->error && net->vio != 0 &&
-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 @@
+@@ -2784,6 +2913,9 @@
+ void set_query_and_id(char *query_arg, uint32 query_length_arg,
+ CHARSET_INFO *cs, query_id_t new_query_id);
+ void set_query_id(query_id_t new_query_id);
++private:
++ void do_set_query_id(query_id_t new_query_id);
++public:
+ void set_open_tables(TABLE *open_tables_arg)
+ {
+ mysql_mutex_lock(&LOCK_thd_data);
+--- a/sql/sql_connect.cc
++++ b/sql/sql_connect.cc
+@@ -721,6 +721,14 @@
+ 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
++ new thread's queries or not. Uses extremely simple algorithm. :)
++ */
++ const ulong& limit= thd->variables.log_slow_rate_limit;
++ thd->write_to_slow_log= opt_slow_query_log_rate_type == SLOG_RT_SESSION &&
++ (limit == 0 || (thd->thread_id % limit) == 0);
++
+ 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
+
+@@ -890,6 +891,7 @@
+ the slow log only if opt_log_slow_admin_statements is set.
+ */
+ thd->enable_slow_log= TRUE;
++ thd->clear_slow_extended();
+ thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
+ thd->set_time();
+ if (!thd->is_valid_time())
+@@ -1440,6 +1442,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 @@
+@@ -1453,13 +1509,47 @@
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))
++ if (!thd->write_to_slow_log && (thd->variables.long_query_time >= 1000000
++ || (ulong) query_exec_time < 1000000))
+ DBUG_VOID_RETURN;
+
+
/*
Do not log administrative statements unless the appropriate option is
set.
-@@ -1818,6 +1853,9 @@
- context.resolve_in_table_list_only(select_lex->
- table_list.first);
+ */
+ if (thd->enable_slow_log)
+ {
+- ulonglong end_utime_of_query= thd->current_utime();
+ thd_proc_info(thd, "logging slow query");
-+ /* Reset the counter at all cases for the extended slow query log */
-+ thd->sent_row_count= 0;
-+
- /*
- Reset warning count for each query that uses tables
- A better approach would be to reset this for any commands
-@@ -5252,6 +5290,21 @@
+ if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
+@@ -5368,7 +5459,8 @@
+ thd->stmt_da->reset_diagnostics_area();
+ thd->warning_info->reset_for_next_command();
thd->rand_used= 0;
- thd->sent_row_count= thd->examined_row_count= 0;
-
-+ thd->bytes_sent_old= thd->status_var.bytes_sent;
-+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
-+ thd->tmp_tables_size= 0;
-+ thd->innodb_was_used= FALSE;
-+ thd->innodb_trx_id= 0;
-+ thd->innodb_io_reads= 0;
-+ thd->innodb_io_read= 0;
-+ thd->innodb_io_reads_wait_timer= 0;
-+ thd->innodb_lock_que_wait_timer= 0;
-+ thd->innodb_innodb_que_wait_timer= 0;
-+ thd->innodb_page_access= 0;
-+ thd->query_plan_flags= QPLAN_NONE;
-+ thd->query_plan_fsort_passes= 0;
-+ thd->last_errno= 0;
+- thd->sent_row_count= thd->examined_row_count= 0;
+
++ thd->clear_slow_extended();
+
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
-@@ -6902,7 +6902,10 @@
+--- a/sql/sql_select.cc
++++ b/sql/sql_select.cc
+@@ -6912,7 +6912,10 @@
{
join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
if (statistics)
}
}
else
-@@ -6916,7 +6919,10 @@
+@@ -6926,7 +6929,10 @@
{
join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED;
if (statistics)
}
}
if (!table->no_keyread)
-@@ -10247,6 +10253,7 @@
+@@ -10274,6 +10280,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);
-@@ -11145,6 +11152,7 @@
+@@ -11175,6 +11182,7 @@
goto err;
}
status_var_increment(table->in_use->status_var.created_tmp_disk_tables);
share->db_record_offset= 1;
DBUG_RETURN(0);
err:
-@@ -11163,6 +11171,14 @@
+@@ -11193,6 +11201,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
+--- 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);
/* 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
-@@ -2898,6 +2898,117 @@
+--- a/sql/sys_vars.cc
++++ b/sql/sys_vars.cc
+@@ -972,6 +972,36 @@
+ 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));
++static Sys_var_ulong sys_query_exec_id(
++ "query_exec_id",
++ "Pretend queries take this query id. When 0 (the default) use the"
++ "actual query id. Used only for debugging.",
++ SESSION_VAR(query_exec_id),
++ NO_CMD_LINE, VALID_RANGE(0, ULONG_MAX), DEFAULT(0), BLOCK_SIZE(1),
++ NO_MUTEX_GUARD, IN_BINLOG);
++#endif
++
+ static bool fix_low_prio_updates(sys_var *self, THD *thd, enum_var_type type)
+ {
+ if (type == OPT_SESSION)
+@@ -2898,6 +2928,134 @@
DEFAULT(FALSE), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
ON_UPDATE(fix_log_state));
+ "Log queries replayed be the slave SQL thread",
+ GLOBAL_VAR(opt_log_slow_slave_statements), CMD_LINE(OPT_ARG),
+ DEFAULT(FALSE));
++static Sys_var_mybool Sys_log_slow_admin_statements(
++ "log_slow_admin_statements",
++ "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements"
++ " to the slow log if it is open.",
++ GLOBAL_VAR(opt_log_slow_admin_statements), CMD_LINE(OPT_ARG),
++ DEFAULT(FALSE));
+static Sys_var_mybool Sys_log_slow_sp_statements(
+ "log_slow_sp_statements",
+ "Log slow statements executed by stored procedure to the slow log if it is open.",
+ "Log slow statements executed by stored procedure to the slow log if it is open. [second, microsecond]",
+ GLOBAL_VAR(opt_slow_query_log_timestamp_precision), CMD_LINE(REQUIRED_ARG),
+ slow_query_log_timestamp_precision_name, DEFAULT(SLOG_SECOND));
-+
++
++const char* slow_query_log_rate_name[]= {"session", "query", 0};
++static Sys_var_enum Sys_slow_query_log_rate_type(
++ "log_slow_rate_type",
++ "Choose the log_slow_rate_limit behavior: session or query. "
++ "When you choose 'session' - every %log_slow_rate_limit connection "
++ "will be processed to slow query log. "
++ "When you choose 'query' - every %log_slow_rate_limit query "
++ "will be processed to slow query log. "
++ "[session, query]",
++ GLOBAL_VAR(opt_slow_query_log_rate_type), CMD_LINE(REQUIRED_ARG),
++ slow_query_log_rate_name, DEFAULT(SLOG_RT_SESSION));
/* 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 */
#else
/* TODO: Add swap info for non-BSD systems */
#endif
-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
+--- 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,41 @@
++--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'};
++ $log_slow_rate_test= $ENV{'log_slow_rate_test'};
++ open(FILE, "$log_file_full_path")
++ or die("Cannot open file $log_file_full_path: $!\n");
++
++ if ($log_slow_rate_test) {
++ $one= 0;
++ $two= 0;
++ $three= 0;
++ while(<FILE>) {
++ $one++ if(/'connection_one'/);
++ $two++ if(/'connection_two'/);
++ $three++ if(/'connection_three'/);
++ }
++ $sum= $one + $two + $three;
++ $zero= 0;
++ if ($one == 0) {
++ $zero++;
++ }
++ if ($two == 0) {
++ $zero++;
++ }
++ if ($three == 0) {
++ $zero++;
++ }
++ print "[log_grep.inc] sum: $sum\n";
++ print "[log_grep.inc] zero: $zero\n";
++ }
++ else {
++ $grep_pattern= $ENV{'grep_pattern'};
++ $lines= 0;
++ while(<FILE>) {
++ $lines++ if (/$grep_pattern/);
++ }
++ print "[log_grep.inc] lines: $lines\n";
++ }
++ close(FILE);
++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
+--- /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,16 @@
++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
++DROP TABLE t;
+--- /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,19 @@
++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
++DROP TABLE t;
++include/rpl_end.inc
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_slave_statements.result
+@@ -0,0 +1,45 @@
++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
++DROP TABLE t;
++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,25 @@
++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
++DROP PROCEDURE test_f;
+--- /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,35 @@
++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
++DROP TABLE t;
+--- /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
+@@ -2385,6 +2385,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
+@@ -2871,6 +2879,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
+@@ -343,6 +343,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;
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_global_control_default.result
+@@ -0,0 +1 @@
++SET GLOBAL slow_query_log_use_global_control=default;
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_global_control_default.test
+@@ -0,0 +1 @@
++SET GLOBAL slow_query_log_use_global_control=default;
+--- /dev/null
++++ b/mysql-test/r/percona_slow_extended_log_error.result
+@@ -0,0 +1,10 @@
++SET long_query_time=0;
++DROP TABLE IF EXISTS t1;
++CREATE TABLE t(a INT);
++[log_start.inc] percona.slow_extended.log_error
++CREATE TABLE t(a INT);
++ERROR 42S01: Table 't' already exists
++[log_stop.inc] percona.slow_extended.log_error
++[log_grep.inc] file: percona.slow_extended.log_error pattern: Last_errno: 1050
++[log_grep.inc] lines: 1
++DROP TABLE t;
+--- /dev/null
++++ b/mysql-test/t/percona_slow_extended_log_error.test
+@@ -0,0 +1,15 @@
++--let log_file=percona.slow_extended.log_error
++SET long_query_time=0;
++--disable_warnings
++DROP TABLE IF EXISTS t1;
++--enable_warnings
++CREATE TABLE t(a INT);
++--source include/log_start.inc
++
++--error ER_TABLE_EXISTS_ERROR
++CREATE TABLE t(a INT);
++
++--source include/log_stop.inc
++--let grep_pattern = Last_errno: 1050
++--source include/log_grep.inc
++DROP TABLE t;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test
+@@ -0,0 +1 @@
++SELECT @@global.log_slow_admin_statements;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_basic.result
+@@ -0,0 +1,3 @@
++SELECT @@global.log_slow_admin_statements;
++@@global.log_slow_admin_statements
++0
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements.result
+@@ -0,0 +1,35 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements OFF
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS OFF
++SET GLOBAL log_slow_admin_statements=true;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements ON
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS ON
++SET GLOBAL log_slow_admin_statements=false;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements OFF
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS OFF
++SET GLOBAL log_slow_admin_statements=foo;
++ERROR 42000: Variable 'log_slow_admin_statements' can't be set to the value of 'foo'
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements OFF
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS OFF
++SET GLOBAL log_slow_admin_statements=default;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements OFF
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS OFF
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config_false.result
+@@ -0,0 +1,6 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements OFF
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS OFF
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config_foo.result
+@@ -0,0 +1,7 @@
++call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF.");
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements OFF
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS OFF
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config_true.result
+@@ -0,0 +1,6 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements ON
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS ON
+--- /dev/null
++++ b/mysql-test/r/percona_log_slow_admin_statements-config.result
+@@ -0,0 +1,6 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++Variable_name Value
++log_slow_admin_statements ON
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++VARIABLE_NAME VARIABLE_VALUE
++LOG_SLOW_ADMIN_STATEMENTS ON
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements=false
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements=foo
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements=true
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config.cnf
+@@ -0,0 +1,2 @@
++[mysqld.1]
++log-slow-admin-statements
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements.test
+@@ -0,0 +1,20 @@
++# default value
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++# set value to 'true'
++SET GLOBAL log_slow_admin_statements=true;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++# set value to 'false'
++SET GLOBAL log_slow_admin_statements=false;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++# set value to 'foo'
++--error ER_WRONG_VALUE_FOR_VAR
++SET GLOBAL log_slow_admin_statements=foo;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
++# set value to default
++SET GLOBAL log_slow_admin_statements=default;
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_false.test
+@@ -0,0 +1,2 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_foo.test
+@@ -0,0 +1,3 @@
++call mtr.add_suppression("option 'log_slow_admin_statements': boolean value 'foo' wasn't recognized. Set to OFF.");
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config_true.test
+@@ -0,0 +1,2 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- /dev/null
++++ b/mysql-test/t/percona_log_slow_admin_statements-config.test
+@@ -0,0 +1,2 @@
++SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
++SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
+--- a/mysql-test/r/mysqld--help-notwin.result
++++ b/mysql-test/r/mysqld--help-notwin.result
+@@ -250,15 +250,38 @@
+ --log-slow-admin-statements
+ Log slow OPTIMIZE, ANALYZE, ALTER and other
+ administrative statements to the slow log if it is open.
++ --log-slow-filter=name
++ Log only the queries that followed certain execution
++ plan. Multiple flags allowed in a comma-separated string.
++ [qc_miss, full_scan, full_join, tmp_table,
++ tmp_table_on_disk, filesort, filesort_on_disk]
+ --log-slow-queries[=name]
+ 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. Must be enabled to activate
+ other slow log options. Deprecated option, use
+ --slow-query-log/--slow-query-log-file instead.
++ --log-slow-rate-limit=#
++ Rate limit statement writes to slow log to only those
++ from every (1/log_slow_rate_limit) session.
++ --log-slow-rate-type=name
++ Choose the log_slow_rate_limit behavior: session or
++ query. When you choose 'session' - every
++ %log_slow_rate_limit connection will be processed to slow
++ query log. When you choose 'query' - every
++ %log_slow_rate_limit query will be processed to slow
++ query log. [session, query]
+ --log-slow-slave-statements
+- Log slow statements executed by slave thread to the slow
+- log if it is open.
++ Log queries replayed be the slave SQL thread
++ --log-slow-sp-statements
++ Log slow statements executed by stored procedure to the
++ slow log if it is open.
++ (Defaults to on; use --skip-log-slow-sp-statements to disable.)
++ --log-slow-verbosity=name
++ Choose how verbose the messages to your slow log will be.
++ Multiple flags allowed in a comma-separated string.
++ [microtime, query_plan, innodb, profiling,
++ profiling_use_getrusage]
+ --log-tc=name Path to transaction coordinator log (used for
+ transactions that affect more than one storage engine,
+ when binary log is disabled).
+@@ -660,6 +683,18 @@
+ Log slow queries to given log file. Defaults logging to
+ hostname-slow.log. Must be enabled to activate other slow
+ log options
++ --slow-query-log-timestamp-always
++ Timestamp is printed for all records of the slow log even
++ if they are same time.
++ --slow-query-log-timestamp-precision=name
++ Log slow statements executed by stored procedure to the
++ slow log if it is open. [second, microsecond]
++ --slow-query-log-use-global-control=name
++ Choose flags, wich always use the global variables.
++ Multiple flags allowed in a comma-separated string.
++ [none, log_slow_filter, log_slow_rate_limit,
++ log_slow_verbosity, long_query_time,
++ min_examined_row_limit, all]
+ --socket=name Socket file to use for connection
+ --sort-buffer-size=#
+ Each thread that needs to do a sort allocates a buffer of
+@@ -817,7 +852,12 @@
+ log-short-format FALSE
+ log-slave-updates FALSE
+ log-slow-admin-statements FALSE
++log-slow-filter
++log-slow-rate-limit 1
++log-slow-rate-type session
+ log-slow-slave-statements FALSE
++log-slow-sp-statements TRUE
++log-slow-verbosity
+ log-tc tc.log
+ log-tc-size 24576
+ log-warnings 1
+@@ -933,6 +973,9 @@
+ slave-type-conversions
+ slow-launch-time 2
+ slow-query-log FALSE
++slow-query-log-timestamp-always FALSE
++slow-query-log-timestamp-precision second
++slow-query-log-use-global-control
+ sort-buffer-size 2097152
+ sporadic-binlog-dump-fail FALSE
+ sql-mode
+--- /dev/null
++++ b/mysql-test/r/percona_slow_query_log_rate.result
+@@ -0,0 +1,78 @@
++SET GLOBAL long_query_time=1;
++SET GLOBAL log_slow_rate_type='session';
++SET GLOBAL log_slow_rate_limit=3;
++[log_start.inc] percona.slow_extended.log_slow_rate_limit
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=1;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=2;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=3;
++SELECT 'connection_three';
++connection_three
++connection_three
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=4;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=5;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=6;
++SELECT 'connection_three';
++connection_three
++connection_three
++[log_stop.inc] percona.slow_extended.log_slow_rate_limit
++[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern:
++[log_grep.inc] sum: 2
++[log_grep.inc] zero: 2
++SET GLOBAL log_slow_rate_type='query';
++SET GLOBAL log_slow_rate_limit=2;
++[log_start.inc] percona.slow_extended.log_slow_rate_limit
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=1;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=2;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=3;
++SELECT 'connection_three';
++connection_three
++connection_three
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=4;
++SELECT 'connection_one';
++connection_one
++connection_one
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=5;
++SELECT 'connection_two';
++connection_two
++connection_two
++SET SESSION query_exec_time=1.1;
++SET SESSION query_exec_id=6;
++SELECT 'connection_three';
++connection_three
++connection_three
++[log_stop.inc] percona.slow_extended.log_slow_rate_limit
++[log_grep.inc] file: percona.slow_extended.log_slow_rate_limit pattern:
++[log_grep.inc] sum: 3
++[log_grep.inc] zero: 0
++SET GLOBAL long_query_time=default;
++SET GLOBAL log_slow_rate_type=default;
++SET GLOBAL log_slow_rate_limit=default;
+--- /dev/null
++++ b/mysql-test/t/percona_slow_query_log_rate.test
+@@ -0,0 +1,16 @@
++--source include/have_debug.inc
++--let log_file=percona.slow_extended.log_slow_rate_limit
++
++SET GLOBAL long_query_time=1;
++
++SET GLOBAL log_slow_rate_type='session';
++SET GLOBAL log_slow_rate_limit=3;
++--source include/percona_slow_query_log_rate.inc
++
++SET GLOBAL log_slow_rate_type='query';
++SET GLOBAL log_slow_rate_limit=2;
++--source include/percona_slow_query_log_rate.inc
++
++SET GLOBAL long_query_time=default;
++SET GLOBAL log_slow_rate_type=default;
++SET GLOBAL log_slow_rate_limit=default;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test
+@@ -0,0 +1 @@
++SELECT @@global.log_slow_rate_limit;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result
+@@ -0,0 +1,3 @@
++SELECT @@global.log_slow_rate_limit;
++@@global.log_slow_rate_limit
++1
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/log_slow_rate_type_basic.test
+@@ -0,0 +1 @@
++SELECT @@global.log_slow_rate_type;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/log_slow_rate_type_basic.result
+@@ -0,0 +1,3 @@
++SELECT @@global.log_slow_rate_type;
++@@global.log_slow_rate_type
++session
+--- /dev/null
++++ b/mysql-test/include/percona_slow_query_log_rate.inc
+@@ -0,0 +1,42 @@
++--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
++--connection default
++--source include/log_start.inc
++
++--connect (connection_one,localhost,root,,)
++--connect (connection_two,localhost,root,,)
++--connect (connection_three,localhost,root,,)
++
++--let i=2
++--let k=1
++
++while($i)
++{
++--connection connection_one
++SET SESSION query_exec_time=1.1;
++eval SET SESSION query_exec_id=$k;
++inc $k;
++SELECT 'connection_one';
++
++--connection connection_two
++SET SESSION query_exec_time=1.1;
++eval SET SESSION query_exec_id=$k;
++inc $k;
++SELECT 'connection_two';
++
++--connection connection_three
++SET SESSION query_exec_time=1.1;
++eval SET SESSION query_exec_id=$k;
++inc $k;
++SELECT 'connection_three';
++
++dec $i;
++}
++
++--connection default
++--disconnect connection_one
++--disconnect connection_two
++--disconnect connection_three
++--source include/wait_condition.inc
++--source include/log_stop.inc
++--let log_slow_rate_test=1
++--source include/log_grep.inc
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/r/query_exec_id_basic.result
+@@ -0,0 +1,2 @@
++SET GLOBAL query_exec_id=default;
++SET SESSION query_exec_id=default;
+--- /dev/null
++++ b/mysql-test/suite/sys_vars/t/query_exec_id_basic.test
+@@ -0,0 +1,4 @@
++--source include/have_debug.inc
++
++SET GLOBAL query_exec_id=default;
++SET SESSION query_exec_id=default;
projects / packages / mysql.git / blobdiff