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 | |
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.
50 files changed, 1499 insertions, 218 deletions
diff --git a/include/my_getopt.h b/include/my_getopt.h index 584c009464d..d1cdb9a2810 100644 --- a/include/my_getopt.h +++ b/include/my_getopt.h @@ -38,6 +38,7 @@ C_MODE_START #define GET_SET 13 #define GET_DOUBLE 14 #define GET_FLAGSET 15 +#define GET_BIT 16 #define GET_ASK_ADDR 128 #define GET_AUTO 64 diff --git a/mysql-test/include/check-warnings.test b/mysql-test/include/check-warnings.test index b2f73c32e35..be347ba46ec 100644 --- a/mysql-test/include/check-warnings.test +++ b/mysql-test/include/check-warnings.test @@ -36,7 +36,7 @@ create temporary table error_log ( let $log_error= $MTR_LOG_ERROR; let $log_warning= $log_error.warnings; -# Try tload the warnings into a temporary table, +# Try to load the warnings into a temporary table, # it might fail with error saying "The MySQL server is # running with the --secure-file-priv" in which case # an attempt to load the file using LOAD DATA LOCAL is made diff --git a/mysql-test/r/log_slow.result b/mysql-test/r/log_slow.result index 510bb929d84..47b8640c556 100644 --- a/mysql-test/r/log_slow.result +++ b/mysql-test/r/log_slow.result @@ -1,6 +1,6 @@ select @@log_slow_filter; @@log_slow_filter -admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk select @@log_slow_rate_limit; @@log_slow_rate_limit 1 @@ -10,7 +10,8 @@ select @@log_slow_verbosity; show variables like "log_slow%"; Variable_name Value log_slow_admin_statements ON -log_slow_filter admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +log_slow_disabled_statements sp +log_slow_filter admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk log_slow_rate_limit 1 log_slow_slave_statements ON log_slow_verbosity diff --git a/mysql-test/r/mysqld--help.result b/mysql-test/r/mysqld--help.result index 45e9a670eb3..71397f6cc84 100644 --- a/mysql-test/r/mysqld--help.result +++ b/mysql-test/r/mysqld--help.result @@ -380,6 +380,9 @@ The following options may be given as the first argument: ALWAYS use row-based binary logging, the security issues do not exist and the binary logging cannot break, so you can safely set this to TRUE + --log-disabled-statements=name + Don't log certain types of statements to general log. Any + combination of: slave, sp --log-error[=name] Log errors to file (instead of stdout). If file name is not specified then 'datadir'/'log-basename'.err or the 'pid-file' path with extension .err is used @@ -388,7 +391,8 @@ The following options may be given as the first argument: FILE, TABLE --log-queries-not-using-indexes Log queries that are executed without benefit of any - index to the slow log if it is open + index to the slow log if it is open. Same as + log_slow_filter='not_using_index' --log-short-format Don't log extra information to update and slow-query logs. --log-slave-updates Tells the slave to log the updates from the slave thread @@ -396,12 +400,20 @@ The following options may be given as the first argument: plan to daisy-chain the slaves --log-slow-admin-statements Log slow OPTIMIZE, ANALYZE, ALTER and other - administrative statements to the slow log if it is open. - (Defaults to on; use --skip-log-slow-admin-statements to disable.) + administrative statements to the slow log if it is open. + Resets or sets the option 'admin' in + log_slow_disabled_statements + --log-slow-disabled-statements=name + Don't log certain types of statements to slow log. Any + combination of: admin, call, slave, sp --log-slow-filter=name - Log only certain types of queries. Any combination of: - admin, filesort, filesort_on_disk, full_join, full_scan, - query_cache, query_cache_miss, tmp_table, + 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. Any + combination of: 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 --log-slow-rate-limit=# Write to slow log every #th slow query. Set to 1 to log @@ -409,8 +421,8 @@ The following options may be given as the first argument: the performance impact of slow logging --log-slow-slave-statements Log slow statements executed by slave thread to the slow - log if it is open. - (Defaults to on; use --skip-log-slow-slave-statements to disable.) + log if it is open. Resets or sets the option 'slave' in + log_slow_disabled_statements --log-slow-verbosity=name Verbosity level for the slow log. Any combination of: innodb, query_plan, explain @@ -1320,6 +1332,7 @@ log-bin-compress FALSE log-bin-compress-min-len 256 log-bin-index (No default value) log-bin-trust-function-creators FALSE +log-disabled-statements sp log-error log-isam myisam.log log-output FILE @@ -1327,7 +1340,8 @@ log-queries-not-using-indexes FALSE log-short-format FALSE log-slave-updates FALSE log-slow-admin-statements TRUE -log-slow-filter admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +log-slow-disabled-statements sp +log-slow-filter admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk log-slow-rate-limit 1 log-slow-slave-statements TRUE log-slow-verbosity diff --git a/mysql-test/r/set_statement.result b/mysql-test/r/set_statement.result index 406ca99a5ea..11d8c6f931f 100644 --- a/mysql-test/r/set_statement.result +++ b/mysql-test/r/set_statement.result @@ -1047,7 +1047,7 @@ set statement long_query_time=default for select @@long_query_time; 10.000000 set statement log_slow_filter=default for select @@log_slow_filter; @@log_slow_filter -admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk set statement log_slow_verbosity=default for select @@log_slow_verbosity; @@log_slow_verbosity diff --git a/mysql-test/r/show_check.result b/mysql-test/r/show_check.result index bf4627f6f68..38a7bd8e1c2 100644 --- a/mysql-test/r/show_check.result +++ b/mysql-test/r/show_check.result @@ -1236,7 +1236,7 @@ select 1 from information_schema.tables limit 1; show status like 'slow_queries'; Variable_name Value Slow_queries 1 -set global log_queries_not_using_indexes=OFF; +set session log_queries_not_using_indexes=OFF; show variables like "log_queries_not_using_indexes"; Variable_name Value log_queries_not_using_indexes OFF @@ -1246,7 +1246,7 @@ select 1 from information_schema.tables limit 1; show status like 'slow_queries'; Variable_name Value Slow_queries 1 -set global log_queries_not_using_indexes=ON; +set session log_queries_not_using_indexes=ON; show variables like "log_queries_not_using_indexes"; Variable_name Value log_queries_not_using_indexes ON diff --git a/mysql-test/suite/sys_vars/r/log_disabled_statements_basic.result b/mysql-test/suite/sys_vars/r/log_disabled_statements_basic.result new file mode 100644 index 00000000000..72bc8449f13 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_disabled_statements_basic.result @@ -0,0 +1,60 @@ +SET @start_global_value = @@global.log_disabled_statements; +select @@global.log_disabled_statements; +@@global.log_disabled_statements +sp +select @@session.log_disabled_statements; +@@session.log_disabled_statements +sp +show global variables like 'log_disabled_statements'; +Variable_name Value +log_disabled_statements sp +show session variables like 'log_disabled_statements'; +Variable_name Value +log_disabled_statements sp +select * from information_schema.global_variables where variable_name='log_disabled_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_DISABLED_STATEMENTS sp +select * from information_schema.session_variables where variable_name='log_disabled_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_DISABLED_STATEMENTS sp +set global log_disabled_statements=1; +select @@global.log_disabled_statements; +@@global.log_disabled_statements +slave +set session log_disabled_statements=1; +select @@session.log_disabled_statements; +@@session.log_disabled_statements +slave +set session log_disabled_statements=1; +select @@session.log_disabled_statements; +@@session.log_disabled_statements +slave +set session log_disabled_statements=2; +select @@session.log_disabled_statements; +@@session.log_disabled_statements +sp +set session log_disabled_statements='slave'; +select @@session.log_disabled_statements; +@@session.log_disabled_statements +slave +set session log_disabled_statements='sp'; +select @@session.log_disabled_statements; +@@session.log_disabled_statements +sp +set session log_disabled_statements='slave,sp'; +select @@session.log_disabled_statements; +@@session.log_disabled_statements +slave,sp +set session log_disabled_statements=''; +select @@session.log_disabled_statements; +@@session.log_disabled_statements + +set session log_disabled_statements=1.1; +ERROR 42000: Incorrect argument type to variable 'log_disabled_statements' +set session log_disabled_statements=1e1; +ERROR 42000: Incorrect argument type to variable 'log_disabled_statements' +set session log_disabled_statements="foo"; +ERROR 42000: Variable 'log_disabled_statements' can't be set to the value of 'foo' +set session log_disabled_statements=1024; +ERROR 42000: Variable 'log_disabled_statements' can't be set to the value of '1024' +SET @@global.log_disabled_statements = @start_global_value; diff --git a/mysql-test/suite/sys_vars/r/log_disabled_statements_func.result b/mysql-test/suite/sys_vars/r/log_disabled_statements_func.result new file mode 100644 index 00000000000..4cfb2adbaac --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_disabled_statements_func.result @@ -0,0 +1,82 @@ +SET @old_log_output= @@global.log_output; +SET @old_log_disable_statements= @@global.log_disabled_statements; +CREATE TABLE t1 (i INT PRIMARY KEY AUTO_INCREMENT, j VARCHAR(255) ) ENGINE=MyISAM; +insert into t1 (j) values ('a'),('b'),('c'),('d'); +SET GLOBAL log_output = 'file,table'; +CREATE PROCEDURE slow() +BEGIN +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b'; +SELECT count(*) from t1 where j>'a'; +END +$ +select @@log_disabled_statements; +@@log_disabled_statements +sp +TRUNCATE TABLE mysql.general_log; +check table t1; +Table Op Msg_type Msg_text +test.t1 check status OK +CALL slow(); +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part2'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT argument FROM mysql.general_log where command_type <> "Close stmt" and command_type <> "Prepare" and argument not like "%general_log%"; +argument +check table t1 +CALL slow() +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part2' +<-- +TRUNCATE TABLE mysql.general_log; +SET SESSION log_disabled_statements=""; +check table t1; +Table Op Msg_type Msg_text +test.t1 check status OK +CALL slow(); +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part3'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT argument FROM mysql.general_log where command_type <> "Close stmt" and command_type <> "Prepare" and argument not like "%general_log%"; +argument +SET SESSION log_disabled_statements="" +check table t1 +CALL slow() +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b' +SELECT count(*) from t1 where j>'a' +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part3' +<-- +TRUNCATE TABLE mysql.general_log; +SET SESSION log_disabled_statements="sp,slave"; +check table t1; +Table Op Msg_type Msg_text +test.t1 check status OK +CALL slow(); +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part4'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT argument FROM mysql.general_log where command_type <> "Close stmt" and command_type <> "Prepare" and argument not like "%general_log%"; +argument +SET SESSION log_disabled_statements="sp,slave" +check table t1 +CALL slow() +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part4' +<-- +DROP TABLE t1; +DROP PROCEDURE slow; +TRUNCATE TABLE mysql.general_log; +SET @@global.log_output= @old_log_output; +SET @@global.log_disabled_statements= @old_log_disable_statements; diff --git a/mysql-test/suite/sys_vars/r/log_queries_not_using_indexes_basic.result b/mysql-test/suite/sys_vars/r/log_queries_not_using_indexes_basic.result index fcb5abbcf91..8952caac8b0 100644 --- a/mysql-test/suite/sys_vars/r/log_queries_not_using_indexes_basic.result +++ b/mysql-test/suite/sys_vars/r/log_queries_not_using_indexes_basic.result @@ -1,4 +1,9 @@ SET @start_value= @@global.log_queries_not_using_indexes; +SET @filter_start_value= @@global.log_slow_filter; +SET @@global.log_queries_not_using_indexes= TRUE; +SET @@session.log_queries_not_using_indexes= TRUE; +SET @@global.log_queries_not_using_indexes= FALSE; +SET @@session.log_queries_not_using_indexes= FALSE; SET @@global.log_queries_not_using_indexes= DEFAULT; SELECT @@global.log_queries_not_using_indexes; @@global.log_queries_not_using_indexes @@ -61,16 +66,41 @@ SET @@global.log_queries_not_using_indexes= @badvar; ERROR 42000: Variable 'log_queries_not_using_indexes' can't be set to the value of 'true' SET GLOBAL log_queries_not_using_indexes= 'DEFAULT'; ERROR 42000: Variable 'log_queries_not_using_indexes' can't be set to the value of 'DEFAULT' -SET log_queries_not_using_indexes= TRUE; -ERROR HY000: Variable 'log_queries_not_using_indexes' is a GLOBAL variable and should be set with SET GLOBAL -SET SESSION log_queries_not_using_indexes= TRUE; -ERROR HY000: Variable 'log_queries_not_using_indexes' is a GLOBAL variable and should be set with SET GLOBAL -SET @@session.log_queries_not_using_indexes= TRUE; -ERROR HY000: Variable 'log_queries_not_using_indexes' is a GLOBAL variable and should be set with SET GLOBAL -SET LOCAL log_queries_not_using_indexes= TRUE; -ERROR HY000: Variable 'log_queries_not_using_indexes' is a GLOBAL variable and should be set with SET GLOBAL SET @@global log_queries_not_using_indexes= TRUE; ERROR 42000: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'log_queries_not_using_indexes= TRUE' at line 1 SET @@SESSION log_queries_not_using_indexes= TRUE; ERROR 42000: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'log_queries_not_using_indexes= TRUE' at line 1 +SET @@SESSION.log_queries_not_using_indexes= TRUE; +select @@SESSION.log_slow_filter; +@@SESSION.log_slow_filter +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 +SET @@SESSION.log_queries_not_using_indexes= FALSE; +select @@SESSION.log_slow_filter; +@@SESSION.log_slow_filter +admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +SET @@GLOBAL.log_queries_not_using_indexes= TRUE; +select @@GLOBAL.log_slow_filter; +@@GLOBAL.log_slow_filter +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 +SET @@GLOBAL.log_queries_not_using_indexes= FALSE; +select @@GLOBAL.log_slow_filter; +@@GLOBAL.log_slow_filter +admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +SET @@SESSION.log_slow_filter=""; +select @@SESSION.log_queries_not_using_indexes; +@@SESSION.log_queries_not_using_indexes +0 +SET @@SESSION.log_slow_filter="not_using_index"; +select @@SESSION.log_queries_not_using_indexes; +@@SESSION.log_queries_not_using_indexes +1 +SET @@GLOBAL.log_slow_filter=""; +select @@GLOBAL.log_queries_not_using_indexes; +@@GLOBAL.log_queries_not_using_indexes +0 +SET @@GLOBAL.log_slow_filter="not_using_index"; +select @@GLOBAL.log_queries_not_using_indexes; +@@GLOBAL.log_queries_not_using_indexes +1 SET @@global.log_queries_not_using_indexes= @start_value; +SET @@global.log_slow_filter= @filter_start_value; diff --git a/mysql-test/suite/sys_vars/r/log_result_errors_basic.result b/mysql-test/suite/sys_vars/r/log_result_errors_basic.result new file mode 100644 index 00000000000..5d3696901a6 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_result_errors_basic.result @@ -0,0 +1,148 @@ +SET @start_global_value = @@global.log_result_errors; +SELECT @start_global_value; +@start_global_value +0 +SET @start_session_value = @@session.log_result_errors; +SELECT @start_session_value; +@start_session_value +0 +'#--------------------FN_DYNVARS_067_01-------------------------#' +SET @@global.log_result_errors = 1; +SET @@global.log_result_errors = DEFAULT; +SELECT @@global.log_result_errors; +@@global.log_result_errors +0 +SET @@session.log_result_errors = 2; +SET @@session.log_result_errors = DEFAULT; +SELECT @@session.log_result_errors; +@@session.log_result_errors +0 +'#--------------------FN_DYNVARS_067_02-------------------------#' +SET @@global.log_result_errors = DEFAULT; +SELECT @@global.log_result_errors = 0; +@@global.log_result_errors = 0 +1 +SET @@session.log_result_errors = DEFAULT; +SELECT @@session.log_result_errors = 0; +@@session.log_result_errors = 0 +1 +'#--------------------FN_DYNVARS_067_03-------------------------#' +SET @@global.log_result_errors = 0; +SELECT @@global.log_result_errors; +@@global.log_result_errors +0 +SET @@global.log_result_errors = 1; +SELECT @@global.log_result_errors; +@@global.log_result_errors +1 +SET @@global.log_result_errors = 3; +SELECT @@global.log_result_errors; +@@global.log_result_errors +3 +'#--------------------FN_DYNVARS_067_04-------------------------#' +SET @@session.log_result_errors = 0; +SELECT @@session.log_result_errors; +@@session.log_result_errors +0 +SET @@session.log_result_errors = 1; +SELECT @@session.log_result_errors; +@@session.log_result_errors +1 +SET @@session.log_result_errors = 3; +SELECT @@session.log_result_errors; +@@session.log_result_errors +3 +'#------------------FN_DYNVARS_067_05-----------------------#' +SET @@global.log_result_errors = 4; +Warnings: +Warning 1292 Truncated incorrect log_result_errors value: '4' +SELECT @@global.log_result_errors; +@@global.log_result_errors +3 +SET @@global.log_result_errors = 65530.34; +ERROR 42000: Incorrect argument type to variable 'log_result_errors' +SELECT @@global.log_result_errors; +@@global.log_result_errors +3 +SET @@global.log_result_errors = test; +ERROR 42000: Incorrect argument type to variable 'log_result_errors' +SELECT @@global.log_result_errors; +@@global.log_result_errors +3 +SET @@session.log_result_errors = -2; +Warnings: +Warning 1292 Truncated incorrect log_result_errors value: '-2' +SELECT @@session.log_result_errors; +@@session.log_result_errors +0 +SET @@session.log_result_errors = 65530.34; +ERROR 42000: Incorrect argument type to variable 'log_result_errors' +SET @@session.log_result_errors = test; +ERROR 42000: Incorrect argument type to variable 'log_result_errors' +SELECT @@session.log_result_errors; +@@session.log_result_errors +0 +'#------------------FN_DYNVARS_067_06-----------------------#' +SELECT @@global.log_result_errors = VARIABLE_VALUE +FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES +WHERE VARIABLE_NAME='log_result_errors'; +@@global.log_result_errors = VARIABLE_VALUE +1 +'#------------------FN_DYNVARS_067_07-----------------------#' +SELECT @@session.log_result_errors = VARIABLE_VALUE +FROM INFORMATION_SCHEMA.SESSION_VARIABLES +WHERE VARIABLE_NAME='log_result_errors'; +@@session.log_result_errors = VARIABLE_VALUE +1 +'#------------------FN_DYNVARS_067_08-----------------------#' +SET @@global.log_result_errors = TRUE; +SELECT @@global.log_result_errors; +@@global.log_result_errors +1 +SET @@global.log_result_errors = FALSE; +SELECT @@global.log_result_errors; +@@global.log_result_errors +0 +'#---------------------FN_DYNVARS_067_09----------------------#' +SET @@session.log_result_errors = 1; +SET @@global.log_result_errors = 2; +SELECT @@log_result_errors = @@global.log_result_errors; +@@log_result_errors = @@global.log_result_errors +0 +'#---------------------FN_DYNVARS_067_10----------------------#' +SET @@session.log_result_errors = 1; +SET @@global.log_result_errors = 2; +SELECT @@log_result_errors = @@local.log_result_errors; +@@log_result_errors = @@local.log_result_errors +1 +SELECT @@local.log_result_errors = @@session.log_result_errors; +@@local.log_result_errors = @@session.log_result_errors +1 +SET @@session.log_result_errors = 1; +create table t1(a int primary key); +insert into t1 values(1); +insert into t1 values(1); +ERROR 23000: Duplicate entry '1' for key 'PRIMARY' +insert ignore into t1 values(1); +Warnings: +Warning 1062 Duplicate entry '1' for key 'PRIMARY' +SET @@session.log_result_errors = 3; +insert ignore into t1 values(1); +Warnings: +Warning 1062 Duplicate entry '1' for key 'PRIMARY' +drop table t1; +SET @@global.log_result_errors = @start_global_value; +SELECT @@global.log_result_errors; +@@global.log_result_errors +0 +SET @@session.log_result_errors = @start_session_value; +SELECT @@session.log_result_errors; +@@session.log_result_errors +0 +[WARN RESULT] affected_rows: 0 status: 2 warning_count: 1 +[WARN RESULT] Level: Warning Code: 1292 'Truncated incorrect log_result_errors value: '4'' +[ERROR RESULT] Code: 1232 'Incorrect argument type to variable 'log_result_errors'' +[ERROR RESULT] Code: 1232 'Incorrect argument type to variable 'log_result_errors'' +[ERROR RESULT] Code: 1062 'Duplicate entry '1' for key 'PRIMARY'' +[WARN RESULT] affected_rows: 0 status: 2 warning_count: 1 +[WARN RESULT] Level: Warning Code: 1062 'Duplicate entry '1' for key 'PRIMARY'' diff --git a/mysql-test/suite/sys_vars/r/log_slow_admin_statements_func.result b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_func.result index daddc4af627..95916d8ce15 100644 --- a/mysql-test/suite/sys_vars/r/log_slow_admin_statements_func.result +++ b/mysql-test/suite/sys_vars/r/log_slow_admin_statements_func.result @@ -10,7 +10,7 @@ j VARCHAR(255) SET GLOBAL log_output = 'file,table'; SET GLOBAL slow_query_log = on; SET SESSION long_query_time = 0; -SET GLOBAL log_slow_admin_statements = on; +SET SESSION log_slow_admin_statements = on; ALTER TABLE log_slow_admin_statements ADD COLUMN k INT DEFAULT 17; CREATE PROCEDURE add_rows() BEGIN @@ -44,3 +44,37 @@ SET @@session.long_query_time= @old_long_query_time; SET @@global.log_slow_admin_statements= @old_log_slow_admin_statements; DROP PROCEDURE add_rows; TRUNCATE TABLE mysql.slow_log; +SET @save_log_slow_disabled_statements= @@global.log_slow_disabled_statements; +SET @@SESSION.log_slow_admin_statements= TRUE; +select @@SESSION.log_slow_disabled_statements; +@@SESSION.log_slow_disabled_statements +sp +SET @@SESSION.log_slow_admin_statements= FALSE; +select @@SESSION.log_slow_disabled_statements; +@@SESSION.log_slow_disabled_statements +admin,sp +SET @@GLOBAL.log_slow_admin_statements= TRUE; +select @@GLOBAL.log_slow_disabled_statements; +@@GLOBAL.log_slow_disabled_statements +sp +SET @@GLOBAL.log_slow_admin_statements= FALSE; +select @@GLOBAL.log_slow_disabled_statements; +@@GLOBAL.log_slow_disabled_statements +admin,sp +SET @@SESSION.log_slow_disabled_statements=""; +select @@SESSION.log_slow_admin_statements; +@@SESSION.log_slow_admin_statements +1 +SET @@SESSION.log_slow_disabled_statements="admin"; +select @@SESSION.log_slow_admin_statements; +@@SESSION.log_slow_admin_statements +0 +SET @@GLOBAL.log_slow_disabled_statements=""; +select @@GLOBAL.log_slow_admin_statements; +@@GLOBAL.log_slow_admin_statements +1 +SET @@GLOBAL.log_slow_disabled_statements="admin"; +select @@GLOBAL.log_slow_admin_statements; +@@GLOBAL.log_slow_admin_statements +0 +SET @@global.log_slow_disabled_statements= @save_log_slow_disabled_statements; diff --git a/mysql-test/suite/sys_vars/r/log_slow_disabled_statements_basic.result b/mysql-test/suite/sys_vars/r/log_slow_disabled_statements_basic.result new file mode 100644 index 00000000000..7ef4931a288 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_disabled_statements_basic.result @@ -0,0 +1,72 @@ +SET @start_global_value = @@global.log_slow_disabled_statements; +select @@global.log_slow_disabled_statements; +@@global.log_slow_disabled_statements +sp +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +sp +show global variables like 'log_slow_disabled_statements'; +Variable_name Value +log_slow_disabled_statements sp +show session variables like 'log_slow_disabled_statements'; +Variable_name Value +log_slow_disabled_statements sp +select * from information_schema.global_variables where variable_name='log_slow_disabled_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_DISABLED_STATEMENTS sp +select * from information_schema.session_variables where variable_name='log_slow_disabled_statements'; +VARIABLE_NAME VARIABLE_VALUE +LOG_SLOW_DISABLED_STATEMENTS sp +set global log_slow_disabled_statements=1; +select @@global.log_slow_disabled_statements; +@@global.log_slow_disabled_statements +admin +set session log_slow_disabled_statements=1; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +admin +set session log_slow_disabled_statements=1; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +admin +set session log_slow_disabled_statements=2; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +call +set session log_slow_disabled_statements=5; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +admin,slave +set session log_slow_disabled_statements='admin'; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +admin +set session log_slow_disabled_statements='slave'; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +slave +set session log_slow_disabled_statements='call'; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +call +set session log_slow_disabled_statements='sp'; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +sp +set session log_slow_disabled_statements='admin,sp,call,slave'; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements +admin,call,slave,sp +set session log_slow_disabled_statements=''; +select @@session.log_slow_disabled_statements; +@@session.log_slow_disabled_statements + +set session log_slow_disabled_statements=1.1; +ERROR 42000: Incorrect argument type to variable 'log_slow_disabled_statements' +set session log_slow_disabled_statements=1e1; +ERROR 42000: Incorrect argument type to variable 'log_slow_disabled_statements' +set session log_slow_disabled_statements="foo"; +ERROR 42000: Variable 'log_slow_disabled_statements' can't be set to the value of 'foo' +set session log_slow_disabled_statements=1024; +ERROR 42000: Variable 'log_slow_disabled_statements' can't be set to the value of '1024' +SET @@global.log_slow_disabled_statements = @start_global_value; diff --git a/mysql-test/suite/sys_vars/r/log_slow_disabled_statements_func.result b/mysql-test/suite/sys_vars/r/log_slow_disabled_statements_func.result new file mode 100644 index 00000000000..80a723a305d --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_disabled_statements_func.result @@ -0,0 +1,166 @@ +SET @old_log_output= @@global.log_output; +SET @old_slow_query_log= @@global.slow_query_log; +SET @old_long_query_time= @@session.long_query_time; +SET @old_log_slow_disable_statements= @@global.log_slow_disabled_statements; +SET @@session.log_slow_verbosity="explain,innodb,query_plan"; +CREATE TABLE t1 (i INT PRIMARY KEY AUTO_INCREMENT, j blob) ENGINE=MyISAM; +insert into t1 (j) values ('a'),('b'),('c'),('d'); +create table t2 (a int auto_increment primary key) engine=myisam; +SET GLOBAL log_output = 'file,table'; +SET GLOBAL slow_query_log = on; +CREATE PROCEDURE slow() +BEGIN +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b'; +SELECT count(*) from t1 where j>'a'; +insert into t2 () values(); +END +$ +CREATE PROCEDURE slow2() +BEGIN +SELECT j,count(*) from t1 group by j; +create temporary table t3 (a int); +alter table t3 add column (b int); +call slow(); +drop temporary table t3; +SELECT j,count(*)+1 from t1 group by j,i; +END +$ +SET SESSION long_query_time = 0; +SELECT @@log_slow_disabled_statements; +@@log_slow_disabled_statements +sp +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra int; +CALL slow2(); +j count(*) +a 1 +b 1 +c 1 +d 1 +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +j count(*)+1 +a 2 +b 2 +c 2 +d 2 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part2'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +sql_text +TRUNCATE TABLE mysql.slow_log +ALTER TABLE t1 add column extra int +CALL slow2() +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part2' +<-- +SET SESSION log_slow_disabled_statements="call,admin"; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra2 int; +CALL slow2(); +j count(*) +a 1 +b 1 +c 1 +d 1 +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +j count(*)+1 +a 2 +b 2 +c 2 +d 2 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part3'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +sql_text +TRUNCATE TABLE mysql.slow_log +SELECT j,count(*) from t1 group by j +create temporary table t3 (a int) +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b' +SELECT count(*) from t1 where j>'a' +insert into t2 () values() +drop temporary table t3 +SELECT j,count(*)+1 from t1 group by j,i +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part3' +<-- +SET SESSION log_slow_disabled_statements=""; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra3 int; +CALL slow2(); +j count(*) +a 1 +b 1 +c 1 +d 1 +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +j count(*)+1 +a 2 +b 2 +c 2 +d 2 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part4'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +sql_text +TRUNCATE TABLE mysql.slow_log +ALTER TABLE t1 add column extra3 int +SELECT j,count(*) from t1 group by j +create temporary table t3 (a int) +alter table t3 add column (b int) +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b' +SELECT count(*) from t1 where j>'a' +insert into t2 () values() +call slow() +drop temporary table t3 +SELECT j,count(*)+1 from t1 group by j,i +CALL slow2() +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part4' +<-- +SET SESSION log_slow_disabled_statements="call,admin,slave,sp"; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra4 int; +CALL slow2(); +j count(*) +a 1 +b 1 +c 1 +d 1 +count(if(sleep(1) >= 0,0,NULL)) +2 +count(*) +3 +j count(*)+1 +a 2 +b 2 +c 2 +d 2 +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part5'; +count(if(sleep(1) >= 0,0,NULL)) +2 +--> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +sql_text +TRUNCATE TABLE mysql.slow_log +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part5' +<-- +DROP TABLE t1,t2; +DROP PROCEDURE slow; +DROP PROCEDURE slow2; +SET @@session.long_query_time= @old_long_query_time; +TRUNCATE TABLE mysql.slow_log; +SET @@global.log_output= @old_log_output; +SET @@global.slow_query_log= @old_slow_query_log; +SET @@global.log_slow_disabled_statements= @old_log_slow_disable_statements; diff --git a/mysql-test/suite/sys_vars/r/log_slow_filter_basic.result b/mysql-test/suite/sys_vars/r/log_slow_filter_basic.result index 5b6eccf2185..0d2549bdbf1 100644 --- a/mysql-test/suite/sys_vars/r/log_slow_filter_basic.result +++ b/mysql-test/suite/sys_vars/r/log_slow_filter_basic.result @@ -1,22 +1,22 @@ SET @start_global_value = @@global.log_slow_filter; select @@global.log_slow_filter; @@global.log_slow_filter -admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk select @@session.log_slow_filter; @@session.log_slow_filter -admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk show global variables like 'log_slow_filter'; Variable_name Value -log_slow_filter admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +log_slow_filter admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk show session variables like 'log_slow_filter'; Variable_name Value -log_slow_filter admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +log_slow_filter admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk select * from information_schema.global_variables where variable_name='log_slow_filter'; VARIABLE_NAME VARIABLE_VALUE -LOG_SLOW_FILTER admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +LOG_SLOW_FILTER admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk select * from information_schema.session_variables where variable_name='log_slow_filter'; VARIABLE_NAME VARIABLE_VALUE -LOG_SLOW_FILTER admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +LOG_SLOW_FILTER admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk set global log_slow_filter=1; select @@global.log_slow_filter; @@global.log_slow_filter @@ -57,6 +57,10 @@ set session log_slow_filter='full_scan'; select @@session.log_slow_filter; @@session.log_slow_filter full_scan +set session log_slow_filter='not_using_index'; +select @@session.log_slow_filter; +@@session.log_slow_filter +not_using_index set session log_slow_filter='query_cache'; select @@session.log_slow_filter; @@session.log_slow_filter @@ -77,10 +81,10 @@ set session log_slow_filter='filesort,query_cache'; select @@session.log_slow_filter; @@session.log_slow_filter filesort,query_cache -set session log_slow_filter='admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk'; +set session log_slow_filter='admin,not_using_index,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk'; select @@session.log_slow_filter; @@session.log_slow_filter -admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +admin,filesort,filesort_on_disk,full_join,full_scan,not_using_index,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk set session log_slow_filter=''; select @@session.log_slow_filter; @@session.log_slow_filter @@ -91,6 +95,6 @@ set session log_slow_filter=1e1; ERROR 42000: Incorrect argument type to variable 'log_slow_filter' set session log_slow_filter="foo"; ERROR 42000: Variable 'log_slow_filter' can't be set to the value of 'foo' -set session log_slow_filter=1024; -ERROR 42000: Variable 'log_slow_filter' can't be set to the value of '1024' +set session log_slow_filter=16384; +ERROR 42000: Variable 'log_slow_filter' can't be set to the value of '16384' SET @@global.log_slow_filter = @start_global_value; diff --git a/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result b/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result index 7be656b2b05..20ece183b86 100644 --- a/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result +++ b/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result @@ -1703,6 +1703,20 @@ NUMERIC_BLOCK_SIZE NULL ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL +VARIABLE_NAME LOG_DISABLED_STATEMENTS +SESSION_VALUE sp +GLOBAL_VALUE sp +GLOBAL_VALUE_ORIGIN COMPILE-TIME +DEFAULT_VALUE sp +VARIABLE_SCOPE SESSION +VARIABLE_TYPE SET +VARIABLE_COMMENT Don't log certain types of statements to general log +NUMERIC_MIN_VALUE NULL +NUMERIC_MAX_VALUE NULL +NUMERIC_BLOCK_SIZE NULL +ENUM_VALUE_LIST slave,sp +READ_ONLY NO +COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_ERROR SESSION_VALUE NULL GLOBAL_VALUE @@ -1732,13 +1746,13 @@ ENUM_VALUE_LIST NONE,FILE,TABLE READ_ONLY NO COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_QUERIES_NOT_USING_INDEXES -SESSION_VALUE NULL +SESSION_VALUE OFF GLOBAL_VALUE OFF GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE OFF -VARIABLE_SCOPE GLOBAL +VARIABLE_SCOPE SESSION VARIABLE_TYPE BOOLEAN -VARIABLE_COMMENT Log queries that are executed without benefit of any index to the slow log if it is open +VARIABLE_COMMENT Log queries that are executed without benefit of any index to the slow log if it is open. Same as log_slow_filter='not_using_index' NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL @@ -1746,31 +1760,45 @@ ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL VARIABLE_NAME LOG_SLOW_ADMIN_STATEMENTS -SESSION_VALUE NULL +SESSION_VALUE ON GLOBAL_VALUE ON GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE ON -VARIABLE_SCOPE GLOBAL +VARIABLE_SCOPE SESSION VARIABLE_TYPE BOOLEAN -VARIABLE_COMMENT Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to the slow log if it is open. +VARIABLE_COMMENT 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 NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL +VARIABLE_NAME LOG_SLOW_DISABLED_STATEMENTS +SESSION_VALUE sp +GLOBAL_VALUE sp +GLOBAL_VALUE_ORIGIN COMPILE-TIME +DEFAULT_VALUE sp +VARIABLE_SCOPE SESSION +VARIABLE_TYPE SET +VARIABLE_COMMENT Don't log certain types of statements to slow log +NUMERIC_MIN_VALUE NULL +NUMERIC_MAX_VALUE NULL +NUMERIC_BLOCK_SIZE NULL +ENUM_VALUE_LIST admin,call,slave,sp +READ_ONLY NO +COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_FILTER -SESSION_VALUE admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk -GLOBAL_VALUE admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +SESSION_VALUE admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +GLOBAL_VALUE admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk GLOBAL_VALUE_ORIGIN COMPILE-TIME -DEFAULT_VALUE admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +DEFAULT_VALUE admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk VARIABLE_SCOPE SESSION VARIABLE_TYPE SET -VARIABLE_COMMENT Log only certain types of queries +VARIABLE_COMMENT 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 NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL -ENUM_VALUE_LIST admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +ENUM_VALUE_LIST 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 READ_ONLY NO COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_RATE_LIMIT @@ -1788,13 +1816,13 @@ ENUM_VALUE_LIST NULL READ_ONLY NO COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_SLAVE_STATEMENTS -SESSION_VALUE NULL +SESSION_VALUE ON GLOBAL_VALUE ON GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE ON -VARIABLE_SCOPE GLOBAL +VARIABLE_SCOPE SESSION VARIABLE_TYPE BOOLEAN -VARIABLE_COMMENT Log slow statements executed by slave thread to the slow log if it is open. +VARIABLE_COMMENT 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 NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL diff --git a/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result b/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result index a94b4f720c6..0867139f37d 100644 --- a/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result +++ b/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result @@ -1871,6 +1871,20 @@ NUMERIC_BLOCK_SIZE NULL ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL +VARIABLE_NAME LOG_DISABLED_STATEMENTS +SESSION_VALUE sp +GLOBAL_VALUE sp +GLOBAL_VALUE_ORIGIN COMPILE-TIME +DEFAULT_VALUE sp +VARIABLE_SCOPE SESSION +VARIABLE_TYPE SET +VARIABLE_COMMENT Don't log certain types of statements to general log +NUMERIC_MIN_VALUE NULL +NUMERIC_MAX_VALUE NULL +NUMERIC_BLOCK_SIZE NULL +ENUM_VALUE_LIST slave,sp +READ_ONLY NO +COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_ERROR SESSION_VALUE NULL GLOBAL_VALUE PATH @@ -1900,13 +1914,13 @@ ENUM_VALUE_LIST NONE,FILE,TABLE READ_ONLY NO COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_QUERIES_NOT_USING_INDEXES -SESSION_VALUE NULL +SESSION_VALUE OFF GLOBAL_VALUE OFF GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE OFF -VARIABLE_SCOPE GLOBAL +VARIABLE_SCOPE SESSION VARIABLE_TYPE BOOLEAN -VARIABLE_COMMENT Log queries that are executed without benefit of any index to the slow log if it is open +VARIABLE_COMMENT Log queries that are executed without benefit of any index to the slow log if it is open. Same as log_slow_filter='not_using_index' NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL @@ -1928,31 +1942,45 @@ ENUM_VALUE_LIST OFF,ON READ_ONLY YES COMMAND_LINE_ARGUMENT OPTIONAL VARIABLE_NAME LOG_SLOW_ADMIN_STATEMENTS -SESSION_VALUE NULL +SESSION_VALUE ON GLOBAL_VALUE ON GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE ON -VARIABLE_SCOPE GLOBAL +VARIABLE_SCOPE SESSION VARIABLE_TYPE BOOLEAN -VARIABLE_COMMENT Log slow OPTIMIZE, ANALYZE, ALTER and other administrative statements to the slow log if it is open. +VARIABLE_COMMENT 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 NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL +VARIABLE_NAME LOG_SLOW_DISABLED_STATEMENTS +SESSION_VALUE sp +GLOBAL_VALUE sp +GLOBAL_VALUE_ORIGIN COMPILE-TIME +DEFAULT_VALUE sp +VARIABLE_SCOPE SESSION +VARIABLE_TYPE SET +VARIABLE_COMMENT Don't log certain types of statements to slow log +NUMERIC_MIN_VALUE NULL +NUMERIC_MAX_VALUE NULL +NUMERIC_BLOCK_SIZE NULL +ENUM_VALUE_LIST admin,call,slave,sp +READ_ONLY NO +COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_FILTER -SESSION_VALUE admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk -GLOBAL_VALUE admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +SESSION_VALUE admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +GLOBAL_VALUE admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk GLOBAL_VALUE_ORIGIN COMPILE-TIME -DEFAULT_VALUE admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +DEFAULT_VALUE admin,filesort,filesort_on_disk,filsort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk VARIABLE_SCOPE SESSION VARIABLE_TYPE SET -VARIABLE_COMMENT Log only certain types of queries +VARIABLE_COMMENT 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 NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL -ENUM_VALUE_LIST admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk +ENUM_VALUE_LIST 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 READ_ONLY NO COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_RATE_LIMIT @@ -1970,13 +1998,13 @@ ENUM_VALUE_LIST NULL READ_ONLY NO COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_SLAVE_STATEMENTS -SESSION_VALUE NULL +SESSION_VALUE ON GLOBAL_VALUE ON GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE ON -VARIABLE_SCOPE GLOBAL +VARIABLE_SCOPE SESSION VARIABLE_TYPE BOOLEAN -VARIABLE_COMMENT Log slow statements executed by slave thread to the slow log if it is open. +VARIABLE_COMMENT 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 NUMERIC_MIN_VALUE NULL NUMERIC_MAX_VALUE NULL NUMERIC_BLOCK_SIZE NULL diff --git a/mysql-test/suite/sys_vars/t/log_disabled_statements_basic.test b/mysql-test/suite/sys_vars/t/log_disabled_statements_basic.test new file mode 100644 index 00000000000..f6191629f91 --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_disabled_statements_basic.test @@ -0,0 +1,51 @@ +# set session + +SET @start_global_value = @@global.log_disabled_statements; + +# +# exists as global only +# +select @@global.log_disabled_statements; +select @@session.log_disabled_statements; +show global variables like 'log_disabled_statements'; +show session variables like 'log_disabled_statements'; +select * from information_schema.global_variables where variable_name='log_disabled_statements'; +select * from information_schema.session_variables where variable_name='log_disabled_statements'; + +# +# show that it's writable +# +set global log_disabled_statements=1; +select @@global.log_disabled_statements; +set session log_disabled_statements=1; +select @@session.log_disabled_statements; + +# +# all valid values +# +set session log_disabled_statements=1; +select @@session.log_disabled_statements; +set session log_disabled_statements=2; +select @@session.log_disabled_statements; +set session log_disabled_statements='slave'; +select @@session.log_disabled_statements; +set session log_disabled_statements='sp'; +select @@session.log_disabled_statements; +set session log_disabled_statements='slave,sp'; +select @@session.log_disabled_statements; +set session log_disabled_statements=''; +select @@session.log_disabled_statements; + +# +# incorrect types/values +# +--error ER_WRONG_TYPE_FOR_VAR +set session log_disabled_statements=1.1; +--error ER_WRONG_TYPE_FOR_VAR +set session log_disabled_statements=1e1; +--error ER_WRONG_VALUE_FOR_VAR +set session log_disabled_statements="foo"; +--error ER_WRONG_VALUE_FOR_VAR +set session log_disabled_statements=1024; + +SET @@global.log_disabled_statements = @start_global_value; diff --git a/mysql-test/suite/sys_vars/t/log_disabled_statements_func-master.opt b/mysql-test/suite/sys_vars/t/log_disabled_statements_func-master.opt new file mode 100644 index 00000000000..c9f62c1ab8a --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_disabled_statements_func-master.opt @@ -0,0 +1,2 @@ +--general-log +--general-log-file=test.log diff --git a/mysql-test/suite/sys_vars/t/log_disabled_statements_func.test b/mysql-test/suite/sys_vars/t/log_disabled_statements_func.test new file mode 100644 index 00000000000..a7a088cdcd9 --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_disabled_statements_func.test @@ -0,0 +1,61 @@ +SET @old_log_output= @@global.log_output; +SET @old_log_disable_statements= @@global.log_disabled_statements; + + +CREATE TABLE t1 (i INT PRIMARY KEY AUTO_INCREMENT, j VARCHAR(255) ) ENGINE=MyISAM; +insert into t1 (j) values ('a'),('b'),('c'),('d'); + +# enable slow logging to table +SET GLOBAL log_output = 'file,table'; + +DELIMITER $; +CREATE PROCEDURE slow() +BEGIN + SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b'; + SELECT count(*) from t1 where j>'a'; +END +$ + +DELIMITER ;$ + +select @@log_disabled_statements; +TRUNCATE TABLE mysql.general_log; +check table t1; +CALL slow(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part2'; + +--echo --> +SELECT argument FROM mysql.general_log where command_type <> "Close stmt" and command_type <> "Prepare" and argument not like "%general_log%"; +--echo <-- + +TRUNCATE TABLE mysql.general_log; +SET SESSION log_disabled_statements=""; +check table t1; +CALL slow(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part3'; + +--echo --> +SELECT argument FROM mysql.general_log where command_type <> "Close stmt" and command_type <> "Prepare" and argument not like "%general_log%"; +--echo <-- + +TRUNCATE TABLE mysql.general_log; +SET SESSION log_disabled_statements="sp,slave"; +check table t1; +CALL slow(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part4'; + +--echo --> +SELECT argument FROM mysql.general_log where command_type <> "Close stmt" and command_type <> "Prepare" and argument not like "%general_log%"; +--echo <-- + +DROP TABLE t1; +DROP PROCEDURE slow; + +# +# Restore setup +# +TRUNCATE TABLE mysql.general_log; +SET @@global.log_output= @old_log_output; +SET @@global.log_disabled_statements= @old_log_disable_statements; + + diff --git a/mysql-test/suite/sys_vars/t/log_queries_not_using_indexes_basic.test b/mysql-test/suite/sys_vars/t/log_queries_not_using_indexes_basic.test index a726bff08d7..5710920464f 100644 --- a/mysql-test/suite/sys_vars/t/log_queries_not_using_indexes_basic.test +++ b/mysql-test/suite/sys_vars/t/log_queries_not_using_indexes_basic.test @@ -21,6 +21,16 @@ ############################################################################### SET @start_value= @@global.log_queries_not_using_indexes; +SET @filter_start_value= @@global.log_slow_filter; + +#################################################################### +# Check that variable is both session and global # +#################################################################### + +SET @@global.log_queries_not_using_indexes= TRUE; +SET @@session.log_queries_not_using_indexes= TRUE; +SET @@global.log_queries_not_using_indexes= FALSE; +SET @@session.log_queries_not_using_indexes= FALSE; #################################################################### # Valid values for boolean # @@ -63,7 +73,7 @@ SET GLOBAL log_queries_not_using_indexes= +0; SELECT @@global.log_queries_not_using_indexes; ################################################################# -# Check if the value in GLOBAL Table matches value in variable # +# Not valid values for the variable # ################################################################# --error ER_WRONG_VALUE_FOR_VAR @@ -88,23 +98,38 @@ SET @@global.log_queries_not_using_indexes= @badvar; --error ER_WRONG_VALUE_FOR_VAR SET GLOBAL log_queries_not_using_indexes= 'DEFAULT'; ---error ER_GLOBAL_VARIABLE -SET log_queries_not_using_indexes= TRUE; - ---error ER_GLOBAL_VARIABLE -SET SESSION log_queries_not_using_indexes= TRUE; - ---error ER_GLOBAL_VARIABLE -SET @@session.log_queries_not_using_indexes= TRUE; - ---error ER_GLOBAL_VARIABLE -SET LOCAL log_queries_not_using_indexes= TRUE; - --error ER_PARSE_ERROR SET @@global log_queries_not_using_indexes= TRUE; --error ER_PARSE_ERROR SET @@SESSION log_queries_not_using_indexes= TRUE; -SET @@global.log_queries_not_using_indexes= @start_value; +#################################################################### +# Ensure that the value matches log_slow_filter # +#################################################################### + +SET @@SESSION.log_queries_not_using_indexes= TRUE; +select @@SESSION.log_slow_filter; +SET @@SESSION.log_queries_not_using_indexes= FALSE; +select @@SESSION.log_slow_filter; +SET @@GLOBAL.log_queries_not_using_indexes= TRUE; +select @@GLOBAL.log_slow_filter; +SET @@GLOBAL.log_queries_not_using_indexes= FALSE; +select @@GLOBAL.log_slow_filter; + +SET @@SESSION.log_slow_filter=""; +select @@SESSION.log_queries_not_using_indexes; +SET @@SESSION.log_slow_filter="not_using_index"; +select @@SESSION.log_queries_not_using_indexes; + +SET @@GLOBAL.log_slow_filter=""; +select @@GLOBAL.log_queries_not_using_indexes; +SET @@GLOBAL.log_slow_filter="not_using_index"; +select @@GLOBAL.log_queries_not_using_indexes; +#################################################################### +# Restore original value # +#################################################################### + +SET @@global.log_queries_not_using_indexes= @start_value; +SET @@global.log_slow_filter= @filter_start_value; diff --git a/mysql-test/suite/sys_vars/t/log_slow_admin_statements_func.test b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_func.test index 78e4d35f69a..97822a0f23a 100644 --- a/mysql-test/suite/sys_vars/t/log_slow_admin_statements_func.test +++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_func.test @@ -16,7 +16,7 @@ CREATE TABLE log_slow_admin_statements ( SET GLOBAL log_output = 'file,table'; SET GLOBAL slow_query_log = on; SET SESSION long_query_time = 0; -SET GLOBAL log_slow_admin_statements = on; +SET SESSION log_slow_admin_statements = on; # test ALTER, OPTIMIZE and CHECK against the table shown up ALTER TABLE log_slow_admin_statements ADD COLUMN k INT DEFAULT 17; @@ -59,3 +59,30 @@ SET @@global.log_slow_admin_statements= @old_log_slow_admin_statements; DROP PROCEDURE add_rows; TRUNCATE TABLE mysql.slow_log; + +# +# Ensure that log_slow_admin_statements maps to log_slow_disable_statements +# + +SET @save_log_slow_disabled_statements= @@global.log_slow_disabled_statements; +SET @@SESSION.log_slow_admin_statements= TRUE; +select @@SESSION.log_slow_disabled_statements; +SET @@SESSION.log_slow_admin_statements= FALSE; +select @@SESSION.log_slow_disabled_statements; +SET @@GLOBAL.log_slow_admin_statements= TRUE; +select @@GLOBAL.log_slow_disabled_statements; +SET @@GLOBAL.log_slow_admin_statements= FALSE; +select @@GLOBAL.log_slow_disabled_statements; + +SET @@SESSION.log_slow_disabled_statements=""; +select @@SESSION.log_slow_admin_statements; +SET @@SESSION.log_slow_disabled_statements="admin"; +select @@SESSION.log_slow_admin_statements; + +SET @@GLOBAL.log_slow_disabled_statements=""; +select @@GLOBAL.log_slow_admin_statements; +SET @@GLOBAL.log_slow_disabled_statements="admin"; +select @@GLOBAL.log_slow_admin_statements; + +SET @@global.log_slow_disabled_statements= @save_log_slow_disabled_statements; + diff --git a/mysql-test/suite/sys_vars/t/log_slow_disabled_statements_basic.test b/mysql-test/suite/sys_vars/t/log_slow_disabled_statements_basic.test new file mode 100644 index 00000000000..77391df6b3c --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_disabled_statements_basic.test @@ -0,0 +1,57 @@ +# set session + +SET @start_global_value = @@global.log_slow_disabled_statements; + +# +# exists as global only +# +select @@global.log_slow_disabled_statements; +select @@session.log_slow_disabled_statements; +show global variables like 'log_slow_disabled_statements'; +show session variables like 'log_slow_disabled_statements'; +select * from information_schema.global_variables where variable_name='log_slow_disabled_statements'; +select * from information_schema.session_variables where variable_name='log_slow_disabled_statements'; + +# +# show that it's writable +# +set global log_slow_disabled_statements=1; +select @@global.log_slow_disabled_statements; +set session log_slow_disabled_statements=1; +select @@session.log_slow_disabled_statements; + +# +# all valid values +# +set session log_slow_disabled_statements=1; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements=2; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements=5; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements='admin'; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements='slave'; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements='call'; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements='sp'; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements='admin,sp,call,slave'; +select @@session.log_slow_disabled_statements; +set session log_slow_disabled_statements=''; +select @@session.log_slow_disabled_statements; + +# +# incorrect types/values +# +--error ER_WRONG_TYPE_FOR_VAR +set session log_slow_disabled_statements=1.1; +--error ER_WRONG_TYPE_FOR_VAR +set session log_slow_disabled_statements=1e1; +--error ER_WRONG_VALUE_FOR_VAR +set session log_slow_disabled_statements="foo"; +--error ER_WRONG_VALUE_FOR_VAR +set session log_slow_disabled_statements=1024; + +SET @@global.log_slow_disabled_statements = @start_global_value; diff --git a/mysql-test/suite/sys_vars/t/log_slow_disabled_statements_func.test b/mysql-test/suite/sys_vars/t/log_slow_disabled_statements_func.test new file mode 100644 index 00000000000..483948c840e --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_disabled_statements_func.test @@ -0,0 +1,92 @@ +SET @old_log_output= @@global.log_output; +SET @old_slow_query_log= @@global.slow_query_log; +SET @old_long_query_time= @@session.long_query_time; +SET @old_log_slow_disable_statements= @@global.log_slow_disabled_statements; + +# Log everything to slow log +SET @@session.log_slow_verbosity="explain,innodb,query_plan"; + +CREATE TABLE t1 (i INT PRIMARY KEY AUTO_INCREMENT, j blob) ENGINE=MyISAM; +insert into t1 (j) values ('a'),('b'),('c'),('d'); +create table t2 (a int auto_increment primary key) engine=myisam; + +# enable slow logging to table +SET GLOBAL log_output = 'file,table'; +SET GLOBAL slow_query_log = on; + +DELIMITER $; +CREATE PROCEDURE slow() +BEGIN + SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b'; + SELECT count(*) from t1 where j>'a'; + insert into t2 () values(); +END +$ + +CREATE PROCEDURE slow2() +BEGIN + SELECT j,count(*) from t1 group by j; + create temporary table t3 (a int); + alter table t3 add column (b int); + call slow(); + drop temporary table t3; + SELECT j,count(*)+1 from t1 group by j,i; +END +$ + +DELIMITER ;$ + +SET SESSION long_query_time = 0; + +SELECT @@log_slow_disabled_statements; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra int; +CALL slow2(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part2'; + +--echo --> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +--echo <-- + +SET SESSION log_slow_disabled_statements="call,admin"; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra2 int; +CALL slow2(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part3'; + +--echo --> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +--echo <-- + +SET SESSION log_slow_disabled_statements=""; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra3 int; +CALL slow2(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part4'; + +--echo --> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +--echo <-- + +SET SESSION log_slow_disabled_statements="call,admin,slave,sp"; +TRUNCATE TABLE mysql.slow_log; +ALTER TABLE t1 add column extra4 int; +CALL slow2(); +SELECT count(if(sleep(1) >= 0,0,NULL)) from t1 where j>'b and part5'; + +--echo --> +SELECT sql_text FROM mysql.slow_log where sql_text <> "Close stmt" and sql_text <> "Prepare"; +--echo <-- + +DROP TABLE t1,t2; +DROP PROCEDURE slow; +DROP PROCEDURE slow2; + +# +# Restore setup +# +SET @@session.long_query_time= @old_long_query_time; +TRUNCATE TABLE mysql.slow_log; +SET @@global.log_output= @old_log_output; +SET @@global.slow_query_log= @old_slow_query_log; +SET @@global.log_slow_disabled_statements= @old_log_slow_disable_statements; diff --git a/mysql-test/suite/sys_vars/t/log_slow_filter_basic.test b/mysql-test/suite/sys_vars/t/log_slow_filter_basic.test index 2891b7ded8b..5309456b3ef 100644 --- a/mysql-test/suite/sys_vars/t/log_slow_filter_basic.test +++ b/mysql-test/suite/sys_vars/t/log_slow_filter_basic.test @@ -39,6 +39,8 @@ set session log_slow_filter='full_join'; select @@session.log_slow_filter; set session log_slow_filter='full_scan'; select @@session.log_slow_filter; +set session log_slow_filter='not_using_index'; +select @@session.log_slow_filter; set session log_slow_filter='query_cache'; select @@session.log_slow_filter; set session log_slow_filter='query_cache_miss'; @@ -49,7 +51,7 @@ set session log_slow_filter='tmp_table_on_disk'; select @@session.log_slow_filter; set session log_slow_filter='filesort,query_cache'; select @@session.log_slow_filter; -set session log_slow_filter='admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk'; +set session log_slow_filter='admin,not_using_index,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk'; select @@session.log_slow_filter; set session log_slow_filter=''; select @@session.log_slow_filter; @@ -64,6 +66,6 @@ set session log_slow_filter=1e1; --error ER_WRONG_VALUE_FOR_VAR set session log_slow_filter="foo"; --error ER_WRONG_VALUE_FOR_VAR -set session log_slow_filter=1024; +set session log_slow_filter=16384; SET @@global.log_slow_filter = @start_global_value; diff --git a/mysql-test/t/show_check.test b/mysql-test/t/show_check.test index 13ca9a528c6..262013e0d2c 100644 --- a/mysql-test/t/show_check.test +++ b/mysql-test/t/show_check.test @@ -954,11 +954,11 @@ flush status; show variables like "log_queries_not_using_indexes"; select 1 from information_schema.tables limit 1; show status like 'slow_queries'; -set global log_queries_not_using_indexes=OFF; +set session log_queries_not_using_indexes=OFF; show variables like "log_queries_not_using_indexes"; select 1 from information_schema.tables limit 1; show status like 'slow_queries'; -set global log_queries_not_using_indexes=ON; +set session log_queries_not_using_indexes=ON; show variables like "log_queries_not_using_indexes"; select 1 from information_schema.tables limit 1; show status like 'slow_queries'; diff --git a/mysys/my_getopt.c b/mysys/my_getopt.c index 57b28d1fd8a..8eff81393d4 100644 --- a/mysys/my_getopt.c +++ b/mysys/my_getopt.c @@ -835,7 +835,27 @@ static int setval(const struct my_option *opts, void *value, char *argument, goto ret; }; } + case GET_BIT: + { + uint tmp; + ulonglong bit= (opts->block_size >= 0 ? + opts->block_size : + -opts->block_size); + /* + This sets a bit stored in a longlong. + The bit to set is stored in block_size. If block_size is positive + then setting the bit means value is true. If block_size is negatitive, + then setting the bit means value is false. + */ + tmp= get_bool_argument(opts, argument); + if (opts->block_size < 0) + tmp= !tmp; + if (tmp) + (*(ulonglong*)value)|= bit; + else + (*(ulonglong*)value)&= ~bit; break; + } case GET_NO_ARG: /* get_one_option has taken care of the value already */ default: /* dummy default to avoid compiler warnings */ break; @@ -1289,6 +1309,19 @@ static void init_one_value(const struct my_option *option, void *variable, case GET_FLAGSET: *((ulonglong*) variable)= (ulonglong) value; break; + case GET_BIT: + { + ulonglong bit= (option->block_size >= 0 ? + option->block_size : + -option->block_size); + if (option->block_size < 0) + value= !value; + if (value) + (*(ulonglong*)variable)|= bit; + else + (*(ulonglong*)variable)&= ~bit; + break; + } case GET_DOUBLE: *((double*) variable)= getopt_ulonglong2double(value); break; @@ -1477,7 +1510,8 @@ void my_print_help(const struct my_option *options) printf("--"); col+= 2 + print_name(optp); if (optp->arg_type == NO_ARG || - (optp->var_type & GET_TYPE_MASK) == GET_BOOL) + (optp->var_type & GET_TYPE_MASK) == GET_BOOL || + (optp->var_type & GET_TYPE_MASK) == GET_BIT) { putchar(' '); col++; @@ -1627,6 +1661,16 @@ void my_print_variables(const struct my_option *options) case GET_BOOL: printf("%s\n", *((my_bool*) value) ? "TRUE" : "FALSE"); break; + case GET_BIT: + { + ulonglong bit= (optp->block_size >= 0 ? + optp->block_size : + -optp->block_size); + my_bool reverse= optp->block_size < 0; + printf("%s\n", ((*((ulonglong*) value) & bit) != 0) ^ reverse ? + "TRUE" : "FALSE"); + break; + } case GET_INT: printf("%d\n", *((int*) value)); break; 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) |