fix for bug #16426

Events: Event-caused statements don't appear in the slow query log
WL#1034

mysql-test/r/events_slow_query.result

+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;

mysql-test/t/events_slow_query-master.opt

+--log-slow-queries

mysql-test/t/events_slow_query.test

+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;

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]",

sql/event_timed.cc

@@ -1162,6 +1162,8 @@ Event_timed::execute(THD *thd, MEM_ROOT *mem_root)
   {
     List<Item> 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

sql/sp_head.cc

@@ -1412,6 +1412,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *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<Item> *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

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 */

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;
 }