diff --git a/mysql-test/r/events_slow_query.result b/mysql-test/r/events_slow_query.result new file mode 100644 index 00000000000..92a8c18300b --- /dev/null +++ b/mysql-test/r/events_slow_query.result @@ -0,0 +1,56 @@ +create database if not exists events_test; +use events_test; +"Save the values" +SET @old_global_long_query_time:=(select get_value()); +SET @old_session_long_query_time:=@@long_query_time; +SHOW VARIABLES LIKE 'log_slow_queries'; +Variable_name Value +log_slow_queries ON +DROP FUNCTION get_value; +TRUNCATE mysql.slow_log; +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +user_host query_time db sql_text +"Set new values" +SET GLOBAL long_query_time=4; +SET SESSION long_query_time=2; +"Check that logging is working" +SELECT SLEEP(3); +SLEEP(3) +0 +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +user_host query_time db sql_text +root[root] @ localhost [] 00:00:03 events_test SELECT SLEEP(3) +TRUNCATE mysql.slow_log; +CREATE TABLE slow_event_test (slo_val tinyint, val tinyint); +"This won't go to the slow log" +CREATE EVENT long_event ON SCHEDULE EVERY 1 MINUTE DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(3); +SELECT * FROM slow_event_test; +slo_val val +SET GLOBAL event_scheduler=1; +"Sleep some more time than the actual event run will take" +"Check our table. Should see 1 row" +SELECT * FROM slow_event_test; +slo_val val +4 0 +"Check slow log. Should not see anything because 3 is under the threshold of 4 for GLOBAL, though over SESSION which is 2" +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +user_host query_time db sql_text +"This should go to the slow log" +SET SESSION long_query_time=10; +ALTER EVENT long_event DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(5); +"Sleep some more time than the actual event run will take" +"Check our table. Should see 2 rows" +SELECT * FROM slow_event_test; +slo_val val +4 0 +4 0 +"Check slow log. Should see 1 row because 5 is over the threshold of 4 for GLOBAL, though under SESSION which is 10" +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +user_host query_time db sql_text +root[root] @ localhost [localhost] 00:00:05 events_test INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(5) +DROP EVENT long_event; +SET GLOBAL long_query_time =@old_global_long_query_time; +SET SESSION long_query_time =@old_session_long_query_time; +TRUNCATE mysql.slow_log; +DROP TABLE slow_event_test; +drop database events_test; diff --git a/mysql-test/t/events_slow_query-master.opt b/mysql-test/t/events_slow_query-master.opt new file mode 100644 index 00000000000..35ff7911705 --- /dev/null +++ b/mysql-test/t/events_slow_query-master.opt @@ -0,0 +1 @@ +--log-slow-queries diff --git a/mysql-test/t/events_slow_query.test b/mysql-test/t/events_slow_query.test new file mode 100644 index 00000000000..2ce0d424622 --- /dev/null +++ b/mysql-test/t/events_slow_query.test @@ -0,0 +1,62 @@ +create database if not exists events_test; +use events_test; + +--disable_query_log +DELIMITER |; +CREATE FUNCTION get_value() + returns INT + deterministic +BEGIN + DECLARE var_name CHAR(255); + DECLARE var_val INT; + DECLARE done INT DEFAULT 0; + DECLARE cur1 CURSOR FOR SHOW GLOBAL VARIABLES LIKE 'long_query_time'; + DECLARE CONTINUE HANDLER FOR SQLSTATE '02000' SET done = 1; + OPEN cur1; + FETCH cur1 INTO var_name, var_val; + CLOSE cur1; + RETURN var_val; +end| +DELIMITER ;| +--enable_query_log +--echo "Save the values" +SET @old_global_long_query_time:=(select get_value()); +SET @old_session_long_query_time:=@@long_query_time; +SHOW VARIABLES LIKE 'log_slow_queries'; +DROP FUNCTION get_value; +TRUNCATE mysql.slow_log; +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +--echo "Set new values" +SET GLOBAL long_query_time=4; +SET SESSION long_query_time=2; +--echo "Check that logging is working" +SELECT SLEEP(3); +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +TRUNCATE mysql.slow_log; +CREATE TABLE slow_event_test (slo_val tinyint, val tinyint); +--echo "This won't go to the slow log" +CREATE EVENT long_event ON SCHEDULE EVERY 1 MINUTE DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(3); +SELECT * FROM slow_event_test; +SET GLOBAL event_scheduler=1; +--echo "Sleep some more time than the actual event run will take" +--sleep 5 +--echo "Check our table. Should see 1 row" +SELECT * FROM slow_event_test; +--echo "Check slow log. Should not see anything because 3 is under the threshold of 4 for GLOBAL, though over SESSION which is 2" +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +--echo "This should go to the slow log" +SET SESSION long_query_time=10; +ALTER EVENT long_event DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(5); +--echo "Sleep some more time than the actual event run will take" +--sleep 7 +--echo "Check our table. Should see 2 rows" +SELECT * FROM slow_event_test; +--echo "Check slow log. Should see 1 row because 5 is over the threshold of 4 for GLOBAL, though under SESSION which is 10" +SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; +DROP EVENT long_event; +SET GLOBAL long_query_time =@old_global_long_query_time; +SET SESSION long_query_time =@old_session_long_query_time; +TRUNCATE mysql.slow_log; +DROP TABLE slow_event_test; + +drop database events_test; diff --git a/sql/event_executor.cc b/sql/event_executor.cc index 60e4c11c619..80b145250d1 100644 --- a/sql/event_executor.cc +++ b/sql/event_executor.cc @@ -273,7 +273,7 @@ init_event_thread(THD* thd) my_net_init(&thd->net, 0); thd->net.read_timeout = slave_net_timeout; thd->slave_thread= 0; - thd->options= OPTION_AUTO_IS_NULL; + thd->options|= OPTION_AUTO_IS_NULL; thd->client_capabilities= CLIENT_LOCAL_FILES; thd->real_id=pthread_self(); VOID(pthread_mutex_lock(&LOCK_thread_count)); @@ -708,6 +708,7 @@ event_executor_worker(void *event_void) thd= current_thd; #endif + thd->enable_slow_log= TRUE; { int ret; sql_print_information("SCHEDULER: Executing event %s.%s of %s [EXPR:%d]", diff --git a/sql/event_timed.cc b/sql/event_timed.cc index 64d5684fbfb..9c818219fe3 100644 --- a/sql/event_timed.cc +++ b/sql/event_timed.cc @@ -1162,6 +1162,8 @@ Event_timed::execute(THD *thd, MEM_ROOT *mem_root) { List empty_item_list; empty_item_list.empty(); + if (thd->enable_slow_log) + sphead->m_flags|= sp_head::LOG_SLOW_STATEMENTS; ret= sphead->execute_procedure(thd, &empty_item_list); } else diff --git a/sql/sp_head.cc b/sql/sp_head.cc index fcc0dc3772e..c0e43e2422e 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -1412,6 +1412,7 @@ sp_head::execute_procedure(THD *thd, List *args) uint params = m_pcont->context_pvars(); sp_rcontext *save_spcont, *octx; sp_rcontext *nctx = NULL; + bool save_enable_slow_log; DBUG_ENTER("sp_head::execute_procedure"); DBUG_PRINT("info", ("procedure %s", m_name.str)); @@ -1510,12 +1511,20 @@ sp_head::execute_procedure(THD *thd, List *args) DBUG_PRINT("info",(" %.*s: eval args done", m_name.length, m_name.str)); } - + if (thd->enable_slow_log && !(m_flags & LOG_SLOW_STATEMENTS)) + { + DBUG_PRINT("info", ("Disabling slow log for the execution")); + save_enable_slow_log= thd->enable_slow_log; + thd->enable_slow_log= FALSE; + } thd->spcont= nctx; - + if (!err_status) err_status= execute(thd); + if (thd->enable_slow_log && !(m_flags & LOG_SLOW_STATEMENTS)) + 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 @@ -2298,6 +2307,8 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) thd->query, thd->query_length) <= 0) { res= m_lex_keeper.reset_lex_and_exec_core(thd, nextp, FALSE, this); + if (!res && unlikely(thd->enable_slow_log)) + log_slow_statement(thd); query_cache_end_of_result(thd); } else diff --git a/sql/sp_head.h b/sql/sp_head.h index a637c466041..83228147430 100644 --- a/sql/sp_head.h +++ b/sql/sp_head.h @@ -124,7 +124,8 @@ public: IS_INVOKED= 32, // Is set if this sp_head is being used HAS_SET_AUTOCOMMIT_STMT= 64,// Is set if a procedure with 'set autocommit' /* Is set if a procedure with COMMIT (implicit or explicit) | ROLLBACK */ - HAS_COMMIT_OR_ROLLBACK= 128 + HAS_COMMIT_OR_ROLLBACK= 128, + LOG_SLOW_STATEMENTS= 256 }; /* TYPE_ENUM_FUNCTION, TYPE_ENUM_PROCEDURE or TYPE_ENUM_TRIGGER */ diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 84b5f981acb..a482018218d 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -2111,6 +2111,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, void log_slow_statement(THD *thd) { + DBUG_ENTER("log_slow_statement"); time_t start_of_query; /* @@ -2142,6 +2143,7 @@ void log_slow_statement(THD *thd) slow_log_print(thd, thd->query, thd->query_length, start_of_query); } } + DBUG_VOID_RETURN; }