database/mariadb
1
0
Fork 0
mirror of https://github.com/MariaDB/server.git synced 2025-07-27 18:02:13 +03:00
Code Activity

New option for slow logging (log_slow_disable_statements)

Browse Source 
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.
This commit is contained in:
Monty
2017-07-21 19:56:41 +03:00
committed by Sergei Golubchik
parent 536215e32f
commit 21518ab2e4
50 changed files with 1501 additions and 220 deletions
Download Patch File Download Diff File Expand all files Collapse all files

70
sql/sql_parse.cc
View File

@ -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;
}
@ -3213,6 +3238,12 @@ mysql_execute_command(THD *thd)
context.resolve_in_table_list_only(select_lex->
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
@ -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;