X-Git-Url: https://git.pld-linux.org/?a=blobdiff_plain;f=slow_extended.patch;h=315b08a05e74e1d9ebf09b1c0a84fc44419b1831;hb=e6de4e01712e8a04bff03088f306913825a22bb3;hp=a7e373dc18afc20209c8e3bd1913414df614f996;hpb=adf0fb138dfeff9e736ccfac9ea148f9e1d53738;p=packages%2Fmysql.git diff --git a/slow_extended.patch b/slow_extended.patch index a7e373d..315b08a 100644 --- a/slow_extended.patch +++ b/slow_extended.patch @@ -5,10 +5,9 @@ #!!! 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); @@ -25,10 +24,9 @@ diff -ruN a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp 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); @@ -45,10 +43,9 @@ diff -ruN a/include/mysql/plugin_auth.h.pp b/include/mysql/plugin_auth.h.pp 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); @@ -65,10 +62,9 @@ diff -ruN a/include/mysql/plugin_ftparser.h.pp b/include/mysql/plugin_ftparser.h 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); @@ -86,9 +82,8 @@ diff -ruN a/include/mysql/plugin.h b/include/mysql/plugin.h /** 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) @@ -115,10 +110,9 @@ diff -ruN /dev/null b/patch_info/slow_extended.info +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) : ('',''); @@ -129,21 +123,19 @@ diff -ruN a/scripts/mysqldumpslow.sh b/scripts/mysqldumpslow.sh $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); } @@ -151,15 +143,15 @@ diff -ruN a/sql/filesort.cc b/sql/filesort.cc #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); @@ -167,9 +159,8 @@ diff -ruN a/sql/filesort.cc b/sql/filesort.cc 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 @@ */ @@ -202,7 +193,16 @@ diff -ruN a/sql/log.cc b/sql/log.cc 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 : "", "[", @@ -211,8 +211,8 @@ diff -ruN a/sql/log.cc b/sql/log.cc 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); @@ -236,29 +236,16 @@ diff -ruN a/sql/log.cc b/sql/log.cc } 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 */ @@ -273,7 +260,7 @@ diff -ruN a/sql/log.cc b/sql/log.cc bool error= 0; DBUG_ENTER("MYSQL_QUERY_LOG::write"); -@@ -2683,17 +2712,28 @@ +@@ -2683,17 +2697,28 @@ if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT)) { @@ -309,9 +296,11 @@ diff -ruN a/sql/log.cc b/sql/log.cc /* 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", @@ -382,9 +371,8 @@ diff -ruN a/sql/log.cc b/sql/log.cc 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, @@ -394,7 +382,7 @@ diff -ruN a/sql/log.h b/sql/log.h 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; @@ -403,7 +391,7 @@ diff -ruN a/sql/log.h b/sql/log.h 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(); @@ -412,7 +400,7 @@ diff -ruN a/sql/log.h b/sql/log.h 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(); @@ -421,10 +409,9 @@ diff -ruN a/sql/log.h b/sql/log.h 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; @@ -432,13 +419,18 @@ diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc +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.", @@ -448,7 +440,7 @@ diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc {"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 @@ -459,7 +451,7 @@ diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc /** 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); @@ -468,10 +460,9 @@ diff -ruN a/sql/mysqld.cc b/sql/mysqld.cc 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; @@ -479,12 +470,12 @@ diff -ruN a/sql/mysqld.h b/sql/mysqld.h +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; @@ -493,10 +484,9 @@ diff -ruN a/sql/slave.cc b/sql/slave.cc 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)); } @@ -505,10 +495,9 @@ diff -ruN a/sql/sp_head.cc b/sql/sp_head.cc { 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); @@ -516,7 +505,7 @@ diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc if (!thd->stmt_da->is_set()) thd->stmt_da->disable_status(); -@@ -1766,6 +1767,7 @@ +@@ -1790,6 +1791,7 @@ err_unlock: unlock(); err: @@ -524,31 +513,30 @@ diff -ruN a/sql/sql_cache.cc b/sql/sql_cache.cc 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" @@ -565,59 +553,175 @@ diff -ruN a/sql/sql_class.cc b/sql/sql_class.cc /** 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 }; @@ -634,6 +738,9 @@ diff -ruN a/sql/sql_class.h b/sql/sql_class.h +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 @@ -651,10 +758,15 @@ diff -ruN a/sql/sql_class.h b/sql/sql_class.h 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; @@ -669,32 +781,67 @@ diff -ruN a/sql/sql_class.h b/sql/sql_class.h 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; @@ -703,43 +850,141 @@ diff -ruN a/sql/sql_class.h b/sql/sql_class.h + 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 @@ -750,6 +995,9 @@ diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc + (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 @@ -757,67 +1005,47 @@ diff -ruN a/sql/sql_parse.cc b/sql/sql_parse.cc + 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) @@ -828,7 +1056,7 @@ diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc } } else -@@ -6916,7 +6919,10 @@ +@@ -6926,7 +6929,10 @@ { join->thd->server_status|=SERVER_QUERY_NO_INDEX_USED; if (statistics) @@ -839,7 +1067,7 @@ diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc } } 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); @@ -847,7 +1075,7 @@ diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc 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); @@ -855,7 +1083,7 @@ diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc 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"); @@ -870,9 +1098,8 @@ diff -ruN a/sql/sql_select.cc b/sql/sql_select.cc // 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); @@ -893,10 +1120,46 @@ diff -ruN a/sql/sql_show.cc b/sql/sql_show.cc /* 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)); @@ -971,6 +1234,12 @@ diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc + "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.", @@ -1010,13 +1279,23 @@ diff -ruN a/sql/sys_vars.cc b/sql/sys_vars.cc + "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 */ @@ -1203,9 +1482,8 @@ diff -ruN a/sql/sql_profile.cc b/sql/sql_profile.cc #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 @@ -1264,3 +1542,1513 @@ diff -ruN a/sql/sql_profile.h b/sql/sql_profile.h }; # 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() { ++ $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() { ++ $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 = @ ++# SET GLOBAL slow_query_log = @ ++# 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() { ++ 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;