From d576ca18154392c64b53ff2ed2ab14be3a71d55c Mon Sep 17 00:00:00 2001 From: unknown Date: Wed, 1 Mar 2006 02:34:22 +0100 Subject: [PATCH] fix for bug #16426 Events: Event-caused statements don't appear in the slow query log WL#1034 sql/event_executor.cc: enable slow logging sql/event_timed.cc: enable slow logging for the anonymous SP sql/sp_head.cc: allow thd->enable_slow_log to be TRUE if only m_flags & sp_head::LOG_SLOW_STATEMENTS Because usually enable_slow_log is 1 in user mode, this second check is needed backup the mode otherwise. sql/sp_head.h: add a new constant for slow queries. SP by default does not log slow queries in the body just the whole CALL could be considered as slow if taking too much time and called directly from the user sql/sql_parse.cc: let us see in the the trace log --- mysql-test/r/events_slow_query.result | 56 ++++++++++++++++++++ mysql-test/t/events_slow_query-master.opt | 1 + mysql-test/t/events_slow_query.test | 62 +++++++++++++++++++++++ sql/event_executor.cc | 3 +- sql/event_timed.cc | 2 + sql/sp_head.cc | 15 +++++- sql/sp_head.h | 3 +- sql/sql_parse.cc | 2 + 8 files changed, 140 insertions(+), 4 deletions(-) create mode 100644 mysql-test/r/events_slow_query.result create mode 100644 mysql-test/t/events_slow_query-master.opt create mode 100644 mysql-test/t/events_slow_query.test 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; }