diff options
author | Monty <monty@mariadb.org> | 2017-07-21 19:56:41 +0300 |
---|---|---|
committer | Sergei Golubchik <serg@mariadb.org> | 2017-08-24 01:05:51 +0200 |
commit | 21518ab2e4538e1a6c9b3a136a93885a98492218 (patch) | |
tree | 53ead8ca7b462bfa253f67e53628c44455318c56 /sql | |
parent | 536215e32fc43aa423684e9807640dcf3453924b (diff) | |
download | mariadb-git-21518ab2e4538e1a6c9b3a136a93885a98492218.tar.gz |
New option for slow logging (log_slow_disable_statements)
This fixes MDEV-7742 and MDEV-8305 (Allow user to specify if stored
procedures should be logged in the slow and general log)
New functionality:
- Added new variables log_slow_disable_statements and log_disable_statements
that can be used to disable logging of certain queries to slow and
general log. Currently supported options are 'admin', 'call', 'slave'
and 'sp'.
Defaults are as before. Only 'sp' (stored procedure statements) is
disabled for slow and general_log.
- Slow log to files now includes the following new information:
- When logging stored procedure statements the name of stored
procedure is logged.
- Number of created tmp_tables, tmp_disk_tables and the space used
by temporary tables.
- When logging 'call', the logged status now contains the sum of all
included statements. Before only 'time' was correct.
- Added filsort_priority_queue as an option for log_slow_filter (this
variable existed before, but was not exposed)
- Added support for BIT types in my_getopt()
Mapped some old variables to bitmaps (old variables can still be used)
- Variable 'log_queries_not_using_indexes' is mapped to
log_slow_filter='not_using_index'
- Variable 'log_slow_slave_statements' is mapped to
log_slow_disabled_statements='slave'
- Variable 'log_slow_admin_statements' is mapped to
log_slow_disabled_statements='admin'
- All the above variables are changed to session variables from global
variables
Other things:
- Simplified LOGGER::log_command. We don't need to check for super if
OPTION_LOG_OFF is set as this flag can only be set if one is a super
user.
- Removed some setting of enable_slow_log as it's guaranteed to be set by
mysql_parse()
- mysql_admin_table() now sets thd->enable_slow_log
- Added prepare_logs_for_admin_command() to reset thd->enable_slow_log if
needed.
- Added new functions to store, restore and add slow query status
- Added new functions to store and restore query start time
- Reorganized Sub_statement_state according to types
- Added code in dispatch_command() to ensure that
thd->reset_for_next_command() is always called for a query.
- Added thd->last_sql_command to simplify checking of what was the type
of the last command. Needed when logging to slow log as lex->sql_command
may have changed before slow logging is called.
- Moved QPLAN_TMP_... to where status for tmp tables are updated
- Added new THD variable, affected_rows, to be able to correctly log
number of affected rows to slow log.
Diffstat (limited to 'sql')
-rw-r--r-- | sql/filesort.cc | 1 | ||||
-rw-r--r-- | sql/log.cc | 76 | ||||
-rw-r--r-- | sql/log_event.cc | 8 | ||||
-rw-r--r-- | sql/log_slow.h | 30 | ||||
-rw-r--r-- | sql/mysqld.cc | 3 | ||||
-rw-r--r-- | sql/mysqld.h | 2 | ||||
-rw-r--r-- | sql/rpl_parallel.cc | 3 | ||||
-rw-r--r-- | sql/set_var.cc | 1 | ||||
-rw-r--r-- | sql/set_var.h | 1 | ||||
-rw-r--r-- | sql/slave.cc | 10 | ||||
-rw-r--r-- | sql/sp_head.cc | 65 | ||||
-rw-r--r-- | sql/sp_rcontext.h | 2 | ||||
-rw-r--r-- | sql/sql_admin.cc | 10 | ||||
-rw-r--r-- | sql/sql_alter.cc | 4 | ||||
-rw-r--r-- | sql/sql_audit.h | 2 | ||||
-rw-r--r-- | sql/sql_cache.cc | 1 | ||||
-rw-r--r-- | sql/sql_class.cc | 67 | ||||
-rw-r--r-- | sql/sql_class.h | 82 | ||||
-rw-r--r-- | sql/sql_parse.cc | 70 | ||||
-rw-r--r-- | sql/sql_partition_admin.cc | 2 | ||||
-rw-r--r-- | sql/sql_select.cc | 10 | ||||
-rw-r--r-- | sql/sql_table.cc | 4 | ||||
-rw-r--r-- | sql/sys_vars.cc | 66 | ||||
-rw-r--r-- | sql/sys_vars.ic | 4 |
24 files changed, 388 insertions, 136 deletions
diff --git a/sql/filesort.cc b/sql/filesort.cc index 8c0b0010b75..04431a2bccc 100644 --- a/sql/filesort.cc +++ b/sql/filesort.cc @@ -37,7 +37,6 @@ #include "bounded_queue.h" #include "filesort_utils.h" #include "sql_select.h" -#include "log_slow.h" #include "debug_sync.h" /// How to write record_ref. diff --git a/sql/log.cc b/sql/log.cc index deba614d096..0afa6662a9a 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -39,11 +39,9 @@ #include "rpl_filter.h" #include "rpl_rli.h" #include "sql_audit.h" -#include "log_slow.h" #include "mysqld.h" #include <my_dir.h> -#include <stdarg.h> #include <m_ctype.h> // For test_if_number #ifdef _WIN32 @@ -56,6 +54,8 @@ #include "sql_show.h" #include "my_pthread.h" #include "wsrep_mysqld.h" +#include "sp_rcontext.h" +#include "sp_head.h" /* max size of the log message */ #define MAX_LOG_BUFFER_SIZE 1024 @@ -2976,6 +2976,7 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time, const char *sql_text, uint sql_text_len) { bool error= 0; + char llbuff[22]; DBUG_ENTER("MYSQL_QUERY_LOG::write"); mysql_mutex_lock(&LOCK_log); @@ -3018,22 +3019,39 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time, sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0); sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0); if (my_b_printf(&log_file, - "# Thread_id: %lu Schema: %s QC_hit: %s\n" \ - "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu\n" \ - "# Rows_affected: %lu\n", + "# Thread_id: %lu Schema: %s QC_hit: %s\n" + "# Query_time: %s Lock_time: %s Rows_sent: %lu Rows_examined: %lu\n" + "# Rows_affected: %lu Bytes_sent: %lu\n", (ulong) thd->thread_id, (thd->db ? thd->db : ""), ((thd->query_plan_flags & QPLAN_QC) ? "Yes" : "No"), query_time_buff, lock_time_buff, (ulong) thd->get_sent_row_count(), (ulong) thd->get_examined_row_count(), - thd->get_stmt_da()->is_ok() ? - (ulong) thd->get_stmt_da()->affected_rows() : - 0) == (size_t) -1) + (ulong) thd->get_affected_rows(), + (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old)) + == (size_t) -1) tmp_errno= errno; + + if ((thd->variables.log_slow_verbosity & LOG_SLOW_VERBOSITY_QUERY_PLAN) + && thd->tmp_tables_used && + my_b_printf(&log_file, + "# Tmp_tables: %lu Tmp_disk_tables: %lu " + "Tmp_table_sizes: %s\n", + (ulong) thd->tmp_tables_used, + (ulong) thd->tmp_tables_disk_used, + llstr(thd->tmp_tables_size, llbuff)) == (uint) -1) + tmp_errno= errno; + + if (thd->spcont) + if (my_b_printf(&log_file, "# Stored_routine: %s\n", + ErrConvDQName(thd->spcont->sp).ptr()) == (uint) -1) + tmp_errno= errno; + if ((thd->variables.log_slow_verbosity & LOG_SLOW_VERBOSITY_QUERY_PLAN) && (thd->query_plan_flags & (QPLAN_FULL_SCAN | QPLAN_FULL_JOIN | QPLAN_TMP_TABLE | - QPLAN_TMP_DISK | QPLAN_FILESORT | QPLAN_FILESORT_DISK)) && + QPLAN_TMP_DISK | QPLAN_FILESORT | QPLAN_FILESORT_DISK | + QPLAN_FILESORT_PRIORITY_QUEUE)) && my_b_printf(&log_file, "# Full_scan: %s Full_join: %s " "Tmp_table: %s Tmp_table_on_disk: %s\n" @@ -3041,8 +3059,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time, "Priority_queue: %s\n", ((thd->query_plan_flags & QPLAN_FULL_SCAN) ? "Yes" : "No"), ((thd->query_plan_flags & QPLAN_FULL_JOIN) ? "Yes" : "No"), - ((thd->query_plan_flags & QPLAN_TMP_TABLE) ? "Yes" : "No"), - ((thd->query_plan_flags & QPLAN_TMP_DISK) ? "Yes" : "No"), + (thd->tmp_tables_used ? "Yes" : "No"), + (thd->tmp_tables_disk_used ? "Yes" : "No"), ((thd->query_plan_flags & QPLAN_FILESORT) ? "Yes" : "No"), ((thd->query_plan_flags & QPLAN_FILESORT_DISK) ? "Yes" : "No"), @@ -6427,31 +6445,29 @@ bool slow_log_print(THD *thd, const char *query, uint query_length, } +/** + Decide if we should log the command to general log + + @retval + FALSE No logging + TRUE Ok to log +*/ + bool LOGGER::log_command(THD *thd, enum enum_server_command command) { -#ifndef NO_EMBEDDED_ACCESS_CHECKS - Security_context *sctx= thd->security_ctx; -#endif /* Log command if we have at least one log event handler enabled and want to log this king of commands */ - if (*general_log_handler_list && (what_to_log & (1L << (uint) command))) - { - if ((thd->variables.option_bits & OPTION_LOG_OFF) -#ifndef NO_EMBEDDED_ACCESS_CHECKS - && (sctx->master_access & SUPER_ACL) -#endif - ) - { - /* No logging */ - return FALSE; - } - - return TRUE; - } + if (!(*general_log_handler_list && (what_to_log & (1L << (uint) command)))) + return FALSE; - return FALSE; + /* + If LOG_SLOW_DISABLE_SLAVE is set when slave thread starts, then + OPTION_LOG_OFF is set. + Only the super user can set this bit. + */ + return !(thd->variables.option_bits & OPTION_LOG_OFF); } @@ -6461,7 +6477,7 @@ bool general_log_print(THD *thd, enum enum_server_command command, va_list args; uint error= 0; - /* Print the message to the buffer if we want to log this king of commands */ + /* Print the message to the buffer if we want to log this kind of commands */ if (! logger.log_command(thd, command)) return FALSE; diff --git a/sql/log_event.cc b/sql/log_event.cc index abfa0b80ed5..9b2e732d413 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -5253,13 +5253,13 @@ int Query_log_event::do_apply_event(rpl_group_info *rgi, if (thd->slave_thread) { /* - The opt_log_slow_slave_statements variable can be changed - dynamically, so we have to set the sql_log_slow respectively. + To be compatible with previous releases, the slave thread uses the global + log_slow_disabled_statements value, wich can be changed dynamically, so we + have to set the sql_log_slow respectively. */ - thd->variables.sql_log_slow= opt_log_slow_slave_statements; + thd->variables.sql_log_slow= !MY_TEST(global_system_variables.log_slow_disabled_statements & LOG_SLOW_DISABLE_SLAVE); } - thd->enable_slow_log= thd->variables.sql_log_slow; mysql_parse(thd, thd->query(), thd->query_length(), &parser_state, FALSE, FALSE); /* Finalize server status flags after executing a statement. */ diff --git a/sql/log_slow.h b/sql/log_slow.h index c52722f0cd7..069c35173b9 100644 --- a/sql/log_slow.h +++ b/sql/log_slow.h @@ -15,6 +15,9 @@ /* Defining what to log to slow log */ +#ifndef LOG_SLOW_INCLUDED +#define LOG_SLOW_INCLUDED + #define LOG_SLOW_VERBOSITY_INIT 0 #define LOG_SLOW_VERBOSITY_INNODB (1U << 0) #define LOG_SLOW_VERBOSITY_QUERY_PLAN (1U << 1) @@ -25,13 +28,26 @@ #define QPLAN_ADMIN (1U << 0) #define QPLAN_FILESORT (1U << 1) #define QPLAN_FILESORT_DISK (1U << 2) -#define QPLAN_FULL_JOIN (1U << 3) -#define QPLAN_FULL_SCAN (1U << 4) -#define QPLAN_QC (1U << 5) -#define QPLAN_QC_NO (1U << 6) -#define QPLAN_TMP_DISK (1U << 7) -#define QPLAN_TMP_TABLE (1U << 8) -#define QPLAN_FILESORT_PRIORITY_QUEUE (1U << 9) +#define QPLAN_FILESORT_PRIORITY_QUEUE (1U << 3) +#define QPLAN_FULL_JOIN (1U << 4) +#define QPLAN_FULL_SCAN (1U << 5) +#define QPLAN_NOT_USING_INDEX (1U << 6) +#define QPLAN_QC (1U << 7) +#define QPLAN_QC_NO (1U << 8) +#define QPLAN_TMP_TABLE (1U << 9) +#define QPLAN_TMP_DISK (1U << 10) /* ... */ #define QPLAN_MAX (1UL << 31) /* reserved as placeholder */ + +/* Bits for log_slow_disabled_statements */ +#define LOG_SLOW_DISABLE_ADMIN (1 << 0) +#define LOG_SLOW_DISABLE_CALL (1 << 1) +#define LOG_SLOW_DISABLE_SLAVE (1 << 2) +#define LOG_SLOW_DISABLE_SP (1 << 3) + +/* Bits for log_disabled_statements */ +#define LOG_DISABLE_SLAVE (1 << 0) +#define LOG_DISABLE_SP (1 << 1) + +#endif /* LOG_SLOW_INCLUDED */ diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 2ef2830e80b..bd34a3fec93 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -396,7 +396,6 @@ my_bool disable_log_notes, opt_support_flashback= 0; static my_bool opt_abort; ulonglong log_output_options; my_bool opt_userstat_running; -my_bool opt_log_queries_not_using_indexes= 0; bool opt_error_log= IF_WIN(1,0); bool opt_disable_networking=0, opt_skip_show_db=0; bool opt_skip_name_resolve=0; @@ -458,8 +457,6 @@ my_bool relay_log_recovery; my_bool opt_sync_frm, opt_allow_suspicious_udfs; my_bool opt_secure_auth= 0; char* opt_secure_file_priv; -my_bool opt_log_slow_admin_statements= 0; -my_bool opt_log_slow_slave_statements= 0; my_bool lower_case_file_system= 0; my_bool opt_large_pages= 0; my_bool opt_super_large_pages= 0; diff --git a/sql/mysqld.h b/sql/mysqld.h index ceefcd2f576..d753eceaa59 100644 --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -116,7 +116,6 @@ extern my_bool opt_backup_progress_log; extern my_bool opt_support_flashback; extern ulonglong log_output_options; extern ulong log_backup_output_options; -extern my_bool opt_log_queries_not_using_indexes; extern bool opt_disable_networking, opt_skip_show_db; extern bool opt_skip_name_resolve; extern bool opt_ignore_builtin_innodb; @@ -143,7 +142,6 @@ extern const char *current_dbug_option; extern char* opt_secure_file_priv; 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 sp_automatic_privileges, opt_noacl; extern ulong use_stat_tables; extern my_bool opt_old_style_user_limits, trust_function_creators; diff --git a/sql/rpl_parallel.cc b/sql/rpl_parallel.cc index b274824a33b..0570b50565e 100644 --- a/sql/rpl_parallel.cc +++ b/sql/rpl_parallel.cc @@ -1008,8 +1008,7 @@ handle_rpl_parallel_thread(void *arg) thd->security_ctx->skip_grants(); thd->variables.max_allowed_packet= slave_max_allowed_packet; thd->slave_thread= 1; - thd->variables.sql_log_slow= opt_log_slow_slave_statements; - thd->variables.log_slow_filter= global_system_variables.log_slow_filter; + set_slave_thread_options(thd); thd->client_capabilities = CLIENT_LOCAL_FILES; thd->net.reading_or_writing= 0; diff --git a/sql/set_var.cc b/sql/set_var.cc index 474bfe683a6..606f9ac511d 100644 --- a/sql/set_var.cc +++ b/sql/set_var.cc @@ -1162,6 +1162,7 @@ int fill_sysvars(THD *thd, TABLE_LIST *tables, COND *cond) { STRING_WITH_LEN("SET") }, // GET_SET 13 { STRING_WITH_LEN("DOUBLE") }, // GET_DOUBLE 14 { STRING_WITH_LEN("FLAGSET") }, // GET_FLAGSET 15 + { STRING_WITH_LEN("BOOLEAN") }, // GET_BIT 16 }; const ulong vartype= (var->option.var_type & GET_TYPE_MASK); const LEX_CSTRING *type= types + vartype; diff --git a/sql/set_var.h b/sql/set_var.h index 8d39854a744..d0143e1e524 100644 --- a/sql/set_var.h +++ b/sql/set_var.h @@ -158,6 +158,7 @@ public: case GET_BOOL: case GET_SET: case GET_FLAGSET: + case GET_BIT: return type != STRING_RESULT && type != INT_RESULT; case GET_DOUBLE: return type != INT_RESULT && type != REAL_RESULT && type != DECIMAL_RESULT; diff --git a/sql/slave.cc b/sql/slave.cc index a48acc13102..fea57a95bee 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -3378,6 +3378,13 @@ void set_slave_thread_options(THD* thd) options&= ~OPTION_BIN_LOG; thd->variables.option_bits= options; thd->variables.completion_type= 0; + + /* For easier test in LOGGER::log_command */ + if (thd->variables.log_disabled_statements & LOG_DISABLE_SLAVE) + thd->variables.option_bits|= OPTION_LOG_OFF; + + thd->variables.sql_log_slow= !MY_TEST(thd->variables.log_slow_disabled_statements & + LOG_SLOW_DISABLE_SLAVE); DBUG_VOID_RETURN; } @@ -3424,8 +3431,7 @@ static int init_slave_thread(THD* thd, Master_info *mi, thd->security_ctx->skip_grants(); thd->slave_thread= 1; thd->connection_name= mi->connection_name; - thd->variables.sql_log_slow= opt_log_slow_slave_statements; - thd->variables.log_slow_filter= global_system_variables.log_slow_filter; + thd->variables.sql_log_slow= !MY_TEST(thd->variables.log_slow_disabled_statements & LOG_SLOW_DISABLE_SLAVE); set_slave_thread_options(thd); thd->client_capabilities = CLIENT_LOCAL_FILES; diff --git a/sql/sp_head.cc b/sql/sp_head.cc index 8865a18749a..c1a194ab9b9 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -1561,9 +1561,8 @@ sp_head::execute_trigger(THD *thd, goto err_with_cleanup; } -#ifdef DBUG_ASSERT_EXISTS + /* Needed by slow log */ nctx->sp= this; -#endif thd->spcont= nctx; @@ -1685,9 +1684,8 @@ sp_head::execute_function(THD *thd, Item **argp, uint argcount, */ thd->restore_active_arena(&call_arena, &backup_arena); -#ifdef DBUG_ASSERT_EXISTS + /* Needed by slow log */ nctx->sp= this; -#endif /* Pass arguments. */ for (arg_no= 0; arg_no < argcount; arg_no++) @@ -1891,9 +1889,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *args) DBUG_RETURN(TRUE); } -#ifdef DBUG_ASSERT_EXISTS octx->sp= 0; -#endif thd->spcont= octx; /* set callers_arena to thd, for upper-level function to work */ @@ -1906,9 +1902,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *args) thd->spcont= save_spcont; DBUG_RETURN(TRUE); } -#ifdef DBUG_ASSERT_EXISTS nctx->sp= this; -#endif if (params > 0) { @@ -2005,13 +1999,32 @@ sp_head::execute_procedure(THD *thd, List<Item> *args) DBUG_PRINT("info",(" %.*s: eval args done", (int) m_name.length, m_name.str)); } + save_enable_slow_log= thd->enable_slow_log; - if (!(m_flags & LOG_SLOW_STATEMENTS) && save_enable_slow_log) + + /* + Disable slow log if: + - Slow logging is enabled (no change needed) + - This is a normal SP (not event log) + - If we have not explicitely disabled logging of SP + */ + if (save_enable_slow_log && + ((!(m_flags & LOG_SLOW_STATEMENTS) && + (thd->variables.log_slow_disabled_statements & LOG_SLOW_DISABLE_SP)))) { DBUG_PRINT("info", ("Disabling slow log for the execution")); thd->enable_slow_log= FALSE; } - if (!(m_flags & LOG_GENERAL_LOG) && !(thd->variables.option_bits & OPTION_LOG_OFF)) + + /* + Disable general log if: + - If general log is enabled (no change needed) + - This is a normal SP (not event log) + - If we have not explicitely disabled logging of SP + */ + if (!(thd->variables.option_bits & OPTION_LOG_OFF) && + (!(m_flags & LOG_GENERAL_LOG) && + (thd->variables.log_disabled_statements & LOG_DISABLE_SP))) { DBUG_PRINT("info", ("Disabling general log for the execution")); save_log_general= true; @@ -2035,6 +2048,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *args) if (save_log_general) thd->variables.option_bits &= ~OPTION_LOG_OFF; thd->enable_slow_log= save_enable_slow_log; + /* In the case when we weren't able to employ reuse mechanism for OUT/INOUT paranmeters, we should reallocate memory. This @@ -3196,14 +3210,29 @@ int sp_instr_stmt::execute(THD *thd, uint *nextp) { int res; + bool save_enable_slow_log; + const CSET_STRING query_backup= thd->query_string; + QUERY_START_TIME_INFO time_info; + Sub_statement_state backup_state; DBUG_ENTER("sp_instr_stmt::execute"); DBUG_PRINT("info", ("command: %d", m_lex_keeper.sql_command())); - const CSET_STRING query_backup= thd->query_string; #if defined(ENABLED_PROFILING) /* This s-p instr is profilable and will be captured. */ thd->profiling.set_query_source(m_query.str, m_query.length); #endif + + if ((save_enable_slow_log= thd->enable_slow_log)) + { + /* + Save start time info for the CALL statement and overwrite it with the + current time for log_slow_statement() to log the individual query timing. + */ + thd->get_time(&time_info); + thd->set_time(); + } + thd->store_slow_query_state(&backup_state); + if (!(res= alloc_query(thd, m_query.str, m_query.length)) && !(res=subst_spvars(thd, this, &m_query))) { @@ -3216,6 +3245,7 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) if (query_cache_send_result_to_client(thd, thd->query(), thd->query_length()) <= 0) { + thd->reset_slow_query_state(); res= m_lex_keeper.reset_lex_and_exec_core(thd, nextp, FALSE, this); bool log_slow= !res && thd->enable_slow_log; @@ -3235,6 +3265,15 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) if (log_slow) log_slow_statement(thd); + + /* + Restore enable_slow_log, that can be changed by a admin or call + command + */ + thd->enable_slow_log= save_enable_slow_log; + + /* Add the number of rows to thd for the 'call' statistics */ + thd->add_slow_query_state(&backup_state); } else { @@ -3255,6 +3294,10 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) thd->get_stmt_da()->reset_diagnostics_area(); } } + /* Restore the original query start time */ + if (thd->enable_slow_log) + thd->set_time(&time_info); + DBUG_RETURN(res || thd->is_error()); } diff --git a/sql/sp_rcontext.h b/sql/sp_rcontext.h index 6ff6e02f737..c4c80ac5a1f 100644 --- a/sql/sp_rcontext.h +++ b/sql/sp_rcontext.h @@ -176,11 +176,9 @@ public: /// of the client/server protocol. bool end_partial_result_set; -#ifdef DBUG_ASSERT_EXISTS /// The stored program for which this runtime context is created. Used for /// checking if correct runtime context is used for variable handling. sp_head *sp; -#endif ///////////////////////////////////////////////////////////////////////// // SP-variables. diff --git a/sql/sql_admin.cc b/sql/sql_admin.cc index d052c040d19..ce12b73a9e2 100644 --- a/sql/sql_admin.cc +++ b/sql/sql_admin.cc @@ -449,10 +449,11 @@ static bool mysql_admin_table(THD* thd, TABLE_LIST* tables, int compl_result_code; bool need_repair_or_alter= 0; wait_for_commit* suspended_wfc; - DBUG_ENTER("mysql_admin_table"); DBUG_PRINT("enter", ("extra_open_options: %u", extra_open_options)); + thd->prepare_logs_for_admin_command(); + field_list.push_back(item= new (thd->mem_root) Item_empty_string(thd, "Table", NAME_CHAR_LEN * 2), thd->mem_root); @@ -1304,7 +1305,6 @@ bool Sql_cmd_analyze_table::execute(THD *thd) FALSE, UINT_MAX, FALSE)) goto error; WSREP_TO_ISOLATION_BEGIN_WRTCHK(NULL, NULL, first_table); - thd->enable_slow_log= opt_log_slow_admin_statements; res= mysql_admin_table(thd, first_table, &m_lex->check_opt, "analyze", lock_type, 1, 0, 0, 0, &handler::ha_analyze, 0); @@ -1335,7 +1335,6 @@ bool Sql_cmd_check_table::execute(THD *thd) if (check_table_access(thd, SELECT_ACL, first_table, TRUE, UINT_MAX, FALSE)) goto error; /* purecov: inspected */ - thd->enable_slow_log= opt_log_slow_admin_statements; res= mysql_admin_table(thd, first_table, &m_lex->check_opt, "check", lock_type, 0, 0, HA_OPEN_FOR_REPAIR, 0, @@ -1360,7 +1359,7 @@ bool Sql_cmd_optimize_table::execute(THD *thd) FALSE, UINT_MAX, FALSE)) goto error; /* purecov: inspected */ WSREP_TO_ISOLATION_BEGIN_WRTCHK(NULL, NULL, first_table); - thd->enable_slow_log= opt_log_slow_admin_statements; + res= (specialflag & SPECIAL_NO_NEW_FUNC) ? mysql_recreate_table(thd, first_table, true) : mysql_admin_table(thd, first_table, &m_lex->check_opt, @@ -1392,7 +1391,8 @@ bool Sql_cmd_repair_table::execute(THD *thd) if (check_table_access(thd, SELECT_ACL | INSERT_ACL, first_table, FALSE, UINT_MAX, FALSE)) goto error; /* purecov: inspected */ - thd->enable_slow_log= opt_log_slow_admin_statements; + thd->enable_slow_log&= !MY_TEST(thd->variables.log_slow_disabled_statements & + LOG_SLOW_DISABLE_ADMIN); WSREP_TO_ISOLATION_BEGIN_WRTCHK(NULL, NULL, first_table); res= mysql_admin_table(thd, first_table, &m_lex->check_opt, "repair", TL_WRITE, 1, diff --git a/sql/sql_alter.cc b/sql/sql_alter.cc index f2f3f7f25d9..3d1e4c0fa65 100644 --- a/sql/sql_alter.cc +++ b/sql/sql_alter.cc @@ -310,7 +310,7 @@ bool Sql_cmd_alter_table::execute(THD *thd) "INDEX DIRECTORY"); create_info.data_file_name= create_info.index_file_name= NULL; - thd->enable_slow_log= opt_log_slow_admin_statements; + thd->prepare_logs_for_admin_command(); #ifdef WITH_WSREP if ((!thd->is_current_stmt_binlog_format_row() || @@ -355,7 +355,7 @@ bool Sql_cmd_discard_import_tablespace::execute(THD *thd) if (check_grant(thd, ALTER_ACL, table_list, false, UINT_MAX, false)) return true; - thd->enable_slow_log= opt_log_slow_admin_statements; + thd->prepare_logs_for_admin_command(); /* Check if we attempt to alter mysql.slow_log or diff --git a/sql/sql_audit.h b/sql/sql_audit.h index 50613e5e439..4979375559b 100644 --- a/sql/sql_audit.h +++ b/sql/sql_audit.h @@ -142,6 +142,7 @@ static inline void mysql_audit_general(THD *thd, uint event_subtype, int error_code, const char *msg) { + DBUG_ENTER("mysql_audit_general"); if (mysql_audit_general_enabled()) { char user_buff[MAX_USER_HOST_SIZE]; @@ -182,6 +183,7 @@ void mysql_audit_general(THD *thd, uint event_subtype, mysql_audit_notify(thd, MYSQL_AUDIT_GENERAL_CLASS, &event); } + DBUG_VOID_RETURN; } static inline diff --git a/sql/sql_cache.cc b/sql/sql_cache.cc index b53d6332eb6..1fc1ff8fa3a 100644 --- a/sql/sql_cache.cc +++ b/sql/sql_cache.cc @@ -345,7 +345,6 @@ TODO list: #include "../storage/myisammrg/ha_myisammrg.h" #include "../storage/myisammrg/myrg_def.h" #include "probes_mysql.h" -#include "log_slow.h" #include "transaction.h" #include "strfunc.h" diff --git a/sql/sql_class.cc b/sql/sql_class.cc index d8c6d0db380..1e18326ec20 100644 --- a/sql/sql_class.cc +++ b/sql/sql_class.cc @@ -5097,10 +5097,7 @@ void THD::reset_sub_statement_state(Sub_statement_state *backup, backup->count_cuted_fields= count_cuted_fields; backup->in_sub_stmt= in_sub_stmt; backup->enable_slow_log= enable_slow_log; - backup->query_plan_flags= query_plan_flags; backup->limit_found_rows= limit_found_rows; - backup->examined_row_count= m_examined_row_count; - backup->sent_row_count= m_sent_row_count; backup->cuted_fields= cuted_fields; backup->client_capabilities= client_capabilities; backup->savepoints= transaction.savepoints; @@ -5108,6 +5105,7 @@ void THD::reset_sub_statement_state(Sub_statement_state *backup, first_successful_insert_id_in_prev_stmt; backup->first_successful_insert_id_in_cur_stmt= first_successful_insert_id_in_cur_stmt; + store_slow_query_state(backup); if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) && !is_current_stmt_binlog_format_row()) @@ -5123,14 +5121,12 @@ void THD::reset_sub_statement_state(Sub_statement_state *backup, /* Disable result sets */ client_capabilities &= ~CLIENT_MULTI_RESULTS; in_sub_stmt|= new_state; - m_examined_row_count= 0; - m_sent_row_count= 0; cuted_fields= 0; transaction.savepoints= 0; first_successful_insert_id_in_cur_stmt= 0; + reset_slow_query_state(); } - void THD::restore_sub_statement_state(Sub_statement_state *backup) { DBUG_ENTER("THD::restore_sub_statement_state"); @@ -5165,7 +5161,6 @@ void THD::restore_sub_statement_state(Sub_statement_state *backup) variables.option_bits= backup->option_bits; in_sub_stmt= backup->in_sub_stmt; enable_slow_log= backup->enable_slow_log; - query_plan_flags= backup->query_plan_flags; first_successful_insert_id_in_prev_stmt= backup->first_successful_insert_id_in_prev_stmt; first_successful_insert_id_in_cur_stmt= @@ -5173,6 +5168,10 @@ void THD::restore_sub_statement_state(Sub_statement_state *backup) limit_found_rows= backup->limit_found_rows; set_sent_row_count(backup->sent_row_count); client_capabilities= backup->client_capabilities; + + /* Restore statistic needed for slow log */ + add_slow_query_state(backup); + /* If we've left sub-statement mode, reset the fatal error flag. Otherwise keep the current value, to propagate it up the sub-statement @@ -5197,6 +5196,56 @@ void THD::restore_sub_statement_state(Sub_statement_state *backup) DBUG_VOID_RETURN; } +/* + Store slow query state at start of a stored procedure statment +*/ + +void THD::store_slow_query_state(Sub_statement_state *backup) +{ + backup->affected_rows= affected_rows; + backup->bytes_sent_old= bytes_sent_old; + backup->examined_row_count= m_examined_row_count; + backup->query_plan_flags= query_plan_flags; + backup->query_plan_fsort_passes= query_plan_fsort_passes; + backup->sent_row_count= m_sent_row_count; + backup->tmp_tables_disk_used= tmp_tables_disk_used; + backup->tmp_tables_size= tmp_tables_size; + backup->tmp_tables_used= tmp_tables_used; +} + +/* Reset variables related to slow query log */ + +void THD::reset_slow_query_state() +{ + affected_rows= 0; + bytes_sent_old= status_var.bytes_sent; + m_examined_row_count= 0; + m_sent_row_count= 0; + query_plan_flags= QPLAN_INIT; + query_plan_fsort_passes= 0; + tmp_tables_disk_used= 0; + tmp_tables_size= 0; + tmp_tables_used= 0; +} + +/* + Add back the stored values to the current counters to be able to get + right status for 'call procedure_name' +*/ + +void THD::add_slow_query_state(Sub_statement_state *backup) +{ + affected_rows+= backup->affected_rows; + bytes_sent_old= backup->bytes_sent_old; + m_examined_row_count+= backup->examined_row_count; + m_sent_row_count+= backup->sent_row_count; + query_plan_flags|= backup->query_plan_flags; + query_plan_fsort_passes+= backup->query_plan_fsort_passes; + tmp_tables_disk_used+= backup->tmp_tables_disk_used; + tmp_tables_size+= backup->tmp_tables_size; + tmp_tables_used+= backup->tmp_tables_used; +} + void THD::set_statement(Statement *stmt) { @@ -5231,6 +5280,8 @@ void THD::inc_examined_row_count(ha_rows count) void THD::inc_status_created_tmp_disk_tables() { + tmp_tables_disk_used++; + query_plan_flags|= QPLAN_TMP_DISK; status_var_increment(status_var.created_tmp_disk_tables_); #ifdef HAVE_PSI_STATEMENT_INTERFACE PSI_STATEMENT_CALL(inc_statement_created_tmp_disk_tables)(m_statement_psi, 1); @@ -5239,6 +5290,8 @@ void THD::inc_status_created_tmp_disk_tables() void THD::inc_status_created_tmp_tables() { + tmp_tables_used++; + query_plan_flags|= QPLAN_TMP_TABLE; status_var_increment(status_var.created_tmp_tables_); #ifdef HAVE_PSI_STATEMENT_INTERFACE PSI_STATEMENT_CALL(inc_statement_created_tmp_tables)(m_statement_psi, 1); diff --git a/sql/sql_class.h b/sql/sql_class.h index f5834186a45..46bd2f6a2b7 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -37,6 +37,7 @@ #include "thr_lock.h" /* thr_lock_type, THR_LOCK_DATA, THR_LOCK_INFO */ #include "thr_timer.h" #include "thr_malloc.h" +#include "log_slow.h" /* LOG_SLOW_DISABLE_... */ #include "sql_digest_stream.h" // sql_digest_state @@ -531,6 +532,8 @@ typedef struct system_variables ulonglong join_buff_space_limit; ulonglong log_slow_filter; ulonglong log_slow_verbosity; + ulonglong log_slow_disabled_statements; + ulonglong log_disabled_statements; ulonglong bulk_insert_buff_size; ulonglong join_buff_size; ulonglong sortbuff_size; @@ -1508,19 +1511,25 @@ public: class Sub_statement_state { public: + Discrete_interval auto_inc_interval_for_cur_row; + Discrete_intervals_list auto_inc_intervals_forced; + SAVEPOINT *savepoints; ulonglong option_bits; ulonglong first_successful_insert_id_in_prev_stmt; ulonglong first_successful_insert_id_in_cur_stmt, insert_id_for_cur_row; - Discrete_interval auto_inc_interval_for_cur_row; - Discrete_intervals_list auto_inc_intervals_forced; ulonglong limit_found_rows; - ha_rows cuted_fields, sent_row_count, examined_row_count; + ulonglong tmp_tables_size; ulonglong client_capabilities; + ulonglong cuted_fields, sent_row_count, examined_row_count; + ulonglong affected_rows; + ulonglong bytes_sent_old; + ulong tmp_tables_used; + ulong tmp_tables_disk_used; + ulong query_plan_fsort_passes; ulong query_plan_flags; uint in_sub_stmt; /* 0, SUB_STMT_TRIGGER or SUB_STMT_FUNCTION */ bool enable_slow_log; bool last_insert_id_used; - SAVEPOINT *savepoints; enum enum_check_fields count_cuted_fields; }; @@ -1988,6 +1997,16 @@ struct wait_for_commit void reinit(); }; +/* + Structure to store the start time for a query +*/ + +typedef struct +{ + my_time_t start_time; + ulong start_time_sec_part; + ulonglong start_utime, utime_after_lock; +} QUERY_START_TIME_INFO; extern "C" void my_message_sql(uint error, const char *str, myf MyFlags); @@ -2687,6 +2706,14 @@ public: { m_row_count_func= row_count_func; } + inline void set_affected_rows(longlong row_count_func) + { + /* + We have to add to affected_rows (used by slow log), as otherwise + information for 'call' will be wrong + */ + affected_rows+= (row_count_func >= 0 ? row_count_func : 0); + } ha_rows cuted_fields; @@ -2716,6 +2743,9 @@ public: ha_rows get_examined_row_count() const { return m_examined_row_count; } + ulonglong get_affected_rows() const + { return affected_rows; } + void set_sent_row_count(ha_rows count); void set_examined_row_count(ha_rows count); @@ -2793,8 +2823,16 @@ public: /* Statement id is thread-wide. This counter is used to generate ids */ ulong statement_id_counter; ulong rand_saved_seed1, rand_saved_seed2; + + /* The following variables are used when printing to slow log */ ulong query_plan_flags; ulong query_plan_fsort_passes; + ulong tmp_tables_used; + ulong tmp_tables_disk_used; + ulonglong tmp_tables_size; + ulonglong bytes_sent_old; + ulonglong affected_rows; /* Number of changed rows */ + pthread_t real_id; /* For debugging */ my_thread_id thread_id, thread_dbug_id; uint32 os_thread_id; @@ -2874,7 +2912,6 @@ public: uint8 failed_com_change_user; bool slave_thread; bool extra_port; /* If extra connection */ - bool no_errors; /** @@ -2918,7 +2955,7 @@ public: */ bool charset_is_system_charset, charset_is_collation_connection; bool charset_is_character_set_filesystem; - bool enable_slow_log; /* enable slow log for current statement */ + bool enable_slow_log; /* Enable slow log for current statement */ bool abort_on_warning; bool got_warning; /* Set on call to push_warning() */ /* set during loop of derived table processing */ @@ -2950,6 +2987,7 @@ public: the query. 0 if no error on the master. */ int slave_expected_error; + enum_sql_command last_sql_command; // Last sql_command exceuted in mysql_execute_command() sp_rcontext *spcont; // SP runtime context sp_cache *sp_proc_cache; @@ -3242,6 +3280,20 @@ public: MYSQL_SET_STATEMENT_LOCK_TIME(m_statement_psi, (utime_after_lock - start_utime)); } + void get_time(QUERY_START_TIME_INFO *time_info) + { + time_info->start_time= start_time; + time_info->start_time_sec_part= start_time_sec_part; + time_info->start_utime= start_utime; + time_info->utime_after_lock= utime_after_lock; + } + void set_time(QUERY_START_TIME_INFO *time_info) + { + start_time= time_info->start_time; + start_time_sec_part= time_info->start_time_sec_part; + start_utime= time_info->start_utime; + utime_after_lock= time_info->utime_after_lock; + } ulonglong current_utime() { return microsecond_interval_timer(); } /* Tell SHOW PROCESSLIST to show time from this point */ @@ -3260,7 +3312,7 @@ public: void update_server_status() { set_time_for_next_stage(); - if (utime_after_query > utime_after_lock + variables.long_query_time) + if (utime_after_query >= utime_after_lock + variables.long_query_time) server_status|= SERVER_QUERY_WAS_SLOW; } inline ulonglong found_rows(void) @@ -3658,6 +3710,9 @@ public: void restore_backup_open_tables_state(Open_tables_backup *backup); void reset_sub_statement_state(Sub_statement_state *backup, uint new_state); void restore_sub_statement_state(Sub_statement_state *backup); + void store_slow_query_state(Sub_statement_state *backup); + void reset_slow_query_state(); + void add_slow_query_state(Sub_statement_state *backup); void set_n_backup_active_arena(Query_arena *set, Query_arena *backup); void restore_active_arena(Query_arena *set, Query_arena *backup); @@ -4457,6 +4512,12 @@ public: */ bool restore_from_local_lex_to_old_lex(LEX *oldlex); + inline void prepare_logs_for_admin_command() + { + enable_slow_log&= !MY_TEST(variables.log_slow_disabled_statements & + LOG_SLOW_DISABLE_ADMIN); + query_plan_flags|= QPLAN_ADMIN; + } }; inline void add_to_active_threads(THD *thd) @@ -4483,11 +4544,12 @@ inline void unlink_not_visible_thd(THD *thd) /** A short cut for thd->get_stmt_da()->set_ok_status(). */ inline void -my_ok(THD *thd, ulonglong affected_rows= 0, ulonglong id= 0, +my_ok(THD *thd, ulonglong affected_rows_arg= 0, ulonglong id= 0, const char *message= NULL) { - thd->set_row_count_func(affected_rows); - thd->get_stmt_da()->set_ok_status(affected_rows, id, message); + thd->set_row_count_func(affected_rows_arg); + thd->set_affected_rows(affected_rows_arg); + thd->get_stmt_da()->set_ok_status(affected_rows_arg, id, message); } diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 9b615c2f1e7..da0ed4a734a 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -99,7 +99,6 @@ #include "debug_sync.h" #include "probes_mysql.h" #include "set_var.h" -#include "log_slow.h" #include "sql_bootstrap.h" #include "sql_sequence.h" @@ -1599,11 +1598,18 @@ bool dispatch_command(enum enum_server_command command, THD *thd, thd->m_statement_psi= MYSQL_REFINE_STATEMENT(thd->m_statement_psi, com_statement_info[command]. m_key); + /* + We should always call reset_for_next_command() before a query. + mysql_parse() will do this for queries. Ensure it's also done + for other commands. + */ + if (command != COM_QUERY) + thd->reset_for_next_command(); thd->set_command(command); /* - Commands which always take a long time are logged into - the slow log only if opt_log_slow_admin_statements is set. + thd->variables.log_slow_disabled_statements defines which statements + are logged to slow log */ thd->enable_slow_log= thd->variables.sql_log_slow; thd->query_plan_flags= QPLAN_INIT; @@ -1886,6 +1892,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, thd->set_query_and_id(beginning_of_next_stmt, length, thd->charset(), next_query_id()); + /* Count each statement from the client. */ @@ -1895,7 +1902,6 @@ bool dispatch_command(enum enum_server_command command, THD *thd, thd->set_time(); /* Reset the query start time. */ parser_state.reset(beginning_of_next_stmt, length); - /* TODO: set thd->lex->sql_command to SQLCOM_END here */ if (WSREP_ON) wsrep_mysql_parse(thd, beginning_of_next_stmt, length, &parser_state, @@ -1953,7 +1959,6 @@ bool dispatch_command(enum enum_server_command command, THD *thd, break; } packet= arg_end + 1; - thd->reset_for_next_command(); // thd->reset_for_next_command reset state => restore it if (is_next_command) { @@ -2045,8 +2050,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, status_var_increment(thd->status_var.com_other); - thd->enable_slow_log&= opt_log_slow_admin_statements; - thd->query_plan_flags|= QPLAN_ADMIN; + thd->prepare_logs_for_admin_command(); if (check_global_access(thd, REPL_SLAVE_ACL)) break; @@ -2422,9 +2426,12 @@ com_multi_end: /* + Log query to slow queries, if it passes filtering + @note This function must call delete_explain_query(). */ + void log_slow_statement(THD *thd) { DBUG_ENTER("log_slow_statement"); @@ -2436,19 +2443,26 @@ void log_slow_statement(THD *thd) */ if (unlikely(thd->in_sub_stmt)) goto end; // Don't set time for sub stmt + if (!thd->enable_slow_log || !global_system_variables.sql_log_slow) + goto end; + if ((thd->server_status & + (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && + !(sql_command_flags[thd->last_sql_command] & CF_STATUS_COMMAND) && + (!thd->variables.log_slow_filter || + (thd->variables.log_slow_filter & QPLAN_NOT_USING_INDEX))) + { + thd->query_plan_flags|= QPLAN_NOT_USING_INDEX; + /* We are always logging no index queries if enabled in filter */ + thd->server_status|= SERVER_QUERY_WAS_SLOW; + } /* Follow the slow log filter configuration. */ - if (!thd->enable_slow_log || !global_system_variables.sql_log_slow || - (thd->variables.log_slow_filter - && !(thd->variables.log_slow_filter & thd->query_plan_flags))) + if (thd->variables.log_slow_filter && + !(thd->variables.log_slow_filter & thd->query_plan_flags)) goto end; - - if (((thd->server_status & SERVER_QUERY_WAS_SLOW) || - ((thd->server_status & - (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) && - opt_log_queries_not_using_indexes && - !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))) && + + if ((thd->server_status & SERVER_QUERY_WAS_SLOW) && thd->get_examined_row_count() >= thd->variables.min_examined_row_limit) { thd->status_var.long_query_count++; @@ -2863,6 +2877,7 @@ static bool do_execute_sp(THD *thd, sp_head *sp) { /* bits that should be cleared in thd->server_status */ uint bits_to_be_cleared= 0; + ulonglong affected_rows; if (sp->m_flags & sp_head::MULTI_RESULTS) { if (!(thd->client_capabilities & CLIENT_MULTI_RESULTS)) @@ -2902,7 +2917,10 @@ static bool do_execute_sp(THD *thd, sp_head *sp) return 1; // Substatement should already have sent error } + affected_rows= thd->affected_rows; // Affected rows for all sub statements + thd->affected_rows= 0; // Reset total, as my_ok() adds to it my_ok(thd, (thd->get_row_count_func() < 0) ? 0 : thd->get_row_count_func()); + thd->affected_rows= affected_rows; // Restore original value return 0; } @@ -3133,6 +3151,13 @@ bool Sql_cmd_call::execute(THD *thd) if (do_execute_sp(thd, sp)) return true; + + /* + Disable slow log for the above call(), if calls are disabled. + Instead we will log the executed statements to the slow log. + */ + if (thd->variables.log_slow_disabled_statements & LOG_SLOW_DISABLE_CALL) + thd->enable_slow_log= 0; } return false; } @@ -3214,6 +3239,12 @@ mysql_execute_command(THD *thd) table_list.first); /* + Remember last commmand executed, so that we can use it in functions called by + dispatch_command() + */ + thd->last_sql_command= lex->sql_command; + + /* Reset warning count for each query that uses tables A better approach would be to reset this for any commands that is not a SHOW command or a select that only access local @@ -4245,8 +4276,7 @@ end_with_restore_list: and thus classify as slow administrative statements just like ALTER TABLE. */ - thd->enable_slow_log&= opt_log_slow_admin_statements; - thd->query_plan_flags|= QPLAN_ADMIN; + thd->prepare_logs_for_admin_command(); bzero((char*) &create_info, sizeof(create_info)); create_info.db_type= 0; @@ -7481,6 +7511,7 @@ void THD::reset_for_next_command() reset_dynamic(&thd->user_var_events); thd->user_var_events_alloc= thd->mem_root; } + thd->enable_slow_log= thd->variables.sql_log_slow; thd->clear_error(); thd->get_stmt_da()->reset_diagnostics_area(); thd->get_stmt_da()->reset_for_next_command(); @@ -7488,8 +7519,7 @@ void THD::reset_for_next_command() thd->m_sent_row_count= thd->m_examined_row_count= 0; thd->accessed_rows_and_keys= 0; - thd->query_plan_flags= QPLAN_INIT; - thd->query_plan_fsort_passes= 0; + reset_slow_query_state(); thd->reset_current_stmt_binlog_format_row(); thd->binlog_unsafe_warning_flags= 0; diff --git a/sql/sql_partition_admin.cc b/sql/sql_partition_admin.cc index 08e8da3f030..df37dd5ff42 100644 --- a/sql/sql_partition_admin.cc +++ b/sql/sql_partition_admin.cc @@ -91,7 +91,7 @@ bool Sql_cmd_alter_table_exchange_partition::execute(THD *thd) /* Not allowed with EXCHANGE PARTITION */ DBUG_ASSERT(!create_info.data_file_name && !create_info.index_file_name); - thd->enable_slow_log= opt_log_slow_admin_statements; + thd->prepare_logs_for_admin_command(); DBUG_RETURN(exchange_partition(thd, first_table, &alter_info)); } diff --git a/sql/sql_select.cc b/sql/sql_select.cc index 047921e6a41..e50b6a0820a 100644 --- a/sql/sql_select.cc +++ b/sql/sql_select.cc @@ -50,7 +50,6 @@ #include "filesort.h" // filesort_free_buffers #include "sql_union.h" // mysql_union #include "opt_subselect.h" -#include "log_slow.h" #include "sql_derived.h" #include "sql_statistics.h" #include "sql_cte.h" @@ -16718,8 +16717,6 @@ create_tmp_table(THD *thd, TMP_TABLE_PARAM *param, List<Item> &fields, (int) distinct, (int) save_sum_fields, (ulong) rows_limit, MY_TEST(group))); - thd->query_plan_flags|= QPLAN_TMP_TABLE; - if (use_temp_pool && !(test_flags & TEST_KEEP_TMP_TABLES)) temp_pool_slot = bitmap_lock_set_next(&temp_pool); @@ -17842,7 +17839,6 @@ bool create_internal_tmp_table(TABLE *table, KEY *keyinfo, table->in_use->inc_status_created_tmp_disk_tables(); table->in_use->inc_status_created_tmp_tables(); - table->in_use->query_plan_flags|= QPLAN_TMP_DISK; share->db_record_offset= 1; table->set_created(); DBUG_RETURN(0); @@ -17997,7 +17993,6 @@ bool create_internal_tmp_table(TABLE *table, KEY *keyinfo, } table->in_use->inc_status_created_tmp_disk_tables(); table->in_use->inc_status_created_tmp_tables(); - table->in_use->query_plan_flags|= QPLAN_TMP_DISK; share->db_record_offset= 1; table->created= TRUE; DBUG_RETURN(0); @@ -18164,7 +18159,12 @@ free_tmp_table(THD *thd, TABLE *entry) { entry->file->ha_index_or_rnd_end(); if (entry->db_stat) + { + entry->file->info(HA_STATUS_VARIABLE); + thd->tmp_tables_size+= (entry->file->stats.data_file_length + + entry->file->stats.index_file_length); entry->file->ha_drop_table(entry->s->table_name.str); + } else entry->file->ha_delete_table(entry->s->table_name.str); delete entry->file; diff --git a/sql/sql_table.cc b/sql/sql_table.cc index e8bc1531de7..17df5d6dbde 100644 --- a/sql/sql_table.cc +++ b/sql/sql_table.cc @@ -9868,8 +9868,8 @@ bool mysql_recreate_table(THD *thd, TABLE_LIST *table_list, bool table_copy) HA_CREATE_INFO create_info; Alter_info alter_info; TABLE_LIST *next_table= table_list->next_global; - DBUG_ENTER("mysql_recreate_table"); + /* Set lock type which is appropriate for ALTER TABLE. */ table_list->lock_type= TL_READ_NO_INSERT; /* Same applies to MDL request. */ @@ -9887,6 +9887,8 @@ bool mysql_recreate_table(THD *thd, TABLE_LIST *table_list, bool table_copy) if (table_copy) alter_info.requested_algorithm= Alter_info::ALTER_TABLE_ALGORITHM_COPY; + thd->prepare_logs_for_admin_command(); + bool res= mysql_alter_table(thd, NullS, NullS, &create_info, table_list, &alter_info, 0, (ORDER *) 0, 0); diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc index f637a6d5c5a..1eaa0acdc9a 100644 --- a/sql/sys_vars.cc +++ b/sql/sys_vars.cc @@ -50,7 +50,6 @@ #include "sql_base.h" // close_cached_tables #include "hostname.h" // host_cache_size #include <myisam.h> -#include "log_slow.h" #include "debug_sync.h" // DEBUG_SYNC #include "sql_show.h" @@ -1203,25 +1202,28 @@ static Sys_var_charptr Sys_log_error( CMD_LINE(OPT_ARG, OPT_LOG_ERROR), IN_FS_CHARSET, DEFAULT(disabled_my_option)); -static Sys_var_mybool Sys_log_queries_not_using_indexes( +static Sys_var_bit Sys_log_queries_not_using_indexes( "log_queries_not_using_indexes", "Log queries that are executed without benefit of any index to the " - "slow log if it is open", - GLOBAL_VAR(opt_log_queries_not_using_indexes), - CMD_LINE(OPT_ARG), DEFAULT(FALSE)); + "slow log if it is open. Same as log_slow_filter='not_using_index'", + SESSION_VAR(log_slow_filter), CMD_LINE(OPT_ARG), QPLAN_NOT_USING_INDEX, + DEFAULT(FALSE)); -static Sys_var_mybool Sys_log_slow_admin_statements( +static Sys_var_bit 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(TRUE)); + "Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements " + "to the slow log if it is open. Resets or sets the option 'admin' in " + "log_slow_disabled_statements", + SESSION_VAR(log_slow_disabled_statements), + CMD_LINE(OPT_ARG), REVERSE(LOG_SLOW_DISABLE_ADMIN), DEFAULT(TRUE)); -static Sys_var_mybool Sys_log_slow_slave_statements( +static Sys_var_bit Sys_log_slow_slave_statements( "log_slow_slave_statements", - "Log slow statements executed by slave thread to the slow log if it is open.", - GLOBAL_VAR(opt_log_slow_slave_statements), - CMD_LINE(OPT_ARG), DEFAULT(TRUE)); + "Log slow statements executed by slave thread to the slow log if it is " + "open. Resets or sets the option 'slave' in " + "log_slow_disabled_statements", + SESSION_VAR(log_slow_disabled_statements), + CMD_LINE(OPT_ARG), REVERSE(LOG_SLOW_DISABLE_SLAVE), DEFAULT(TRUE)); static Sys_var_ulong Sys_log_warnings( "log_warnings", @@ -4355,6 +4357,7 @@ static bool fix_log_state(sys_var *self, THD *thd, enum_var_type type) return res; } + static bool check_not_empty_set(sys_var *self, THD *thd, set_var *var) { return var->save_result.ulonglong_value == 0; @@ -5246,15 +5249,42 @@ static Sys_var_keycache Sys_key_cache_segments( ON_UPDATE(repartition_keycache)); static const char *log_slow_filter_names[]= -{ "admin", "filesort", "filesort_on_disk", "full_join", "full_scan", - "query_cache", "query_cache_miss", "tmp_table", "tmp_table_on_disk", 0 +{ + "admin", "filesort", "filesort_on_disk", "filsort_priority_queue", + "full_join", "full_scan", "not_using_index", "query_cache", + "query_cache_miss", "tmp_table", "tmp_table_on_disk", 0 }; + + static Sys_var_set Sys_log_slow_filter( "log_slow_filter", - "Log only certain types of queries", + "Log only certain types of queries to the slow log. If variable empty alll kind of queries are logged. All types are bound by slow_query_time, except 'not_using_index' which is always logged if enabled", SESSION_VAR(log_slow_filter), CMD_LINE(REQUIRED_ARG), log_slow_filter_names, - DEFAULT(my_set_bits(array_elements(log_slow_filter_names)-1))); + /* by default we log all queries except 'not_using_index' */ + DEFAULT(my_set_bits(array_elements(log_slow_filter_names)-1) & + ~QPLAN_NOT_USING_INDEX)); + +static const char *log_slow_disabled_statements_names[]= +{ "admin", "call", "slave", "sp", 0 }; + +static const char *log_disabled_statements_names[]= +{ "slave", "sp", 0 }; + +static Sys_var_set Sys_log_slow_disabled_statements( + "log_slow_disabled_statements", + "Don't log certain types of statements to slow log", + SESSION_VAR(log_slow_disabled_statements), CMD_LINE(REQUIRED_ARG), + log_slow_disabled_statements_names, + DEFAULT(LOG_SLOW_DISABLE_SP)); + +static Sys_var_set Sys_log_disabled_statements( + "log_disabled_statements", + "Don't log certain types of statements to general log", + SESSION_VAR(log_disabled_statements), CMD_LINE(REQUIRED_ARG), + log_disabled_statements_names, + DEFAULT(LOG_DISABLE_SP), + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(check_has_super)); static const char *default_regex_flags_names[]= { diff --git a/sql/sys_vars.ic b/sql/sys_vars.ic index f3837f0246a..0b104625159 100644 --- a/sql/sys_vars.ic +++ b/sql/sys_vars.ic @@ -1764,12 +1764,12 @@ public: binlog_status_arg, on_check_func, on_update_func, substitute) { - option.var_type|= GET_BOOL; + option.var_type|= GET_BIT; reverse_semantics= my_count_bits(bitmask_arg) > 1; bitmask= reverse_semantics ? ~bitmask_arg : bitmask_arg; + option.block_size= reverse_semantics ? -(long) bitmask : bitmask; set(global_var_ptr(), def_val); SYSVAR_ASSERT(def_val < 2); - SYSVAR_ASSERT(getopt.id < 0); // force NO_CMD_LINE SYSVAR_ASSERT(size == sizeof(ulonglong)); } bool session_update(THD *thd, set_var *var) |