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

+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 @@ class sp_head :private Query_arena
     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;
 }