Commit e38822d2 authored by andrey@lmy004's avatar andrey@lmy004

Merge ahristov@bk-internal.mysql.com:/home/bk/mysql-5.1-new

into lmy004.:/work/mysql-5.1-bug17494
parents f4c1a0d4 a9884c4c
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;
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;
...@@ -273,7 +273,7 @@ init_event_thread(THD* thd) ...@@ -273,7 +273,7 @@ init_event_thread(THD* thd)
my_net_init(&thd->net, 0); my_net_init(&thd->net, 0);
thd->net.read_timeout = slave_net_timeout; thd->net.read_timeout = slave_net_timeout;
thd->slave_thread= 0; thd->slave_thread= 0;
thd->options= OPTION_AUTO_IS_NULL; thd->options|= OPTION_AUTO_IS_NULL;
thd->client_capabilities= CLIENT_LOCAL_FILES; thd->client_capabilities= CLIENT_LOCAL_FILES;
thd->real_id=pthread_self(); thd->real_id=pthread_self();
VOID(pthread_mutex_lock(&LOCK_thread_count)); VOID(pthread_mutex_lock(&LOCK_thread_count));
...@@ -708,6 +708,7 @@ event_executor_worker(void *event_void) ...@@ -708,6 +708,7 @@ event_executor_worker(void *event_void)
thd= current_thd; thd= current_thd;
#endif #endif
thd->enable_slow_log= TRUE;
{ {
int ret; int ret;
sql_print_information("SCHEDULER: Executing event %s.%s of %s [EXPR:%d]", sql_print_information("SCHEDULER: Executing event %s.%s of %s [EXPR:%d]",
......
...@@ -1162,6 +1162,8 @@ Event_timed::execute(THD *thd, MEM_ROOT *mem_root) ...@@ -1162,6 +1162,8 @@ Event_timed::execute(THD *thd, MEM_ROOT *mem_root)
{ {
List<Item> empty_item_list; List<Item> empty_item_list;
empty_item_list.empty(); 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); ret= sphead->execute_procedure(thd, &empty_item_list);
} }
else else
......
...@@ -1412,6 +1412,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *args) ...@@ -1412,6 +1412,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *args)
uint params = m_pcont->context_pvars(); uint params = m_pcont->context_pvars();
sp_rcontext *save_spcont, *octx; sp_rcontext *save_spcont, *octx;
sp_rcontext *nctx = NULL; sp_rcontext *nctx = NULL;
bool save_enable_slow_log;
DBUG_ENTER("sp_head::execute_procedure"); DBUG_ENTER("sp_head::execute_procedure");
DBUG_PRINT("info", ("procedure %s", m_name.str)); DBUG_PRINT("info", ("procedure %s", m_name.str));
...@@ -1510,12 +1511,20 @@ sp_head::execute_procedure(THD *thd, List<Item> *args) ...@@ -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)); 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; thd->spcont= nctx;
if (!err_status) if (!err_status)
err_status= execute(thd); 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 In the case when we weren't able to employ reuse mechanism for
OUT/INOUT paranmeters, we should reallocate memory. This OUT/INOUT paranmeters, we should reallocate memory. This
...@@ -2298,6 +2307,8 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) ...@@ -2298,6 +2307,8 @@ sp_instr_stmt::execute(THD *thd, uint *nextp)
thd->query, thd->query_length) <= 0) thd->query, thd->query_length) <= 0)
{ {
res= m_lex_keeper.reset_lex_and_exec_core(thd, nextp, FALSE, this); 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); query_cache_end_of_result(thd);
} }
else else
......
...@@ -124,7 +124,8 @@ public: ...@@ -124,7 +124,8 @@ public:
IS_INVOKED= 32, // Is set if this sp_head is being used 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' HAS_SET_AUTOCOMMIT_STMT= 64,// Is set if a procedure with 'set autocommit'
/* Is set if a procedure with COMMIT (implicit or explicit) | ROLLBACK */ /* 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 */ /* TYPE_ENUM_FUNCTION, TYPE_ENUM_PROCEDURE or TYPE_ENUM_TRIGGER */
......
...@@ -2111,6 +2111,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd, ...@@ -2111,6 +2111,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
void log_slow_statement(THD *thd) void log_slow_statement(THD *thd)
{ {
DBUG_ENTER("log_slow_statement");
time_t start_of_query; time_t start_of_query;
/* /*
...@@ -2142,6 +2143,7 @@ void log_slow_statement(THD *thd) ...@@ -2142,6 +2143,7 @@ void log_slow_statement(THD *thd)
slow_log_print(thd, thd->query, thd->query_length, start_of_query); slow_log_print(thd, thd->query, thd->query_length, start_of_query);
} }
} }
DBUG_VOID_RETURN;
} }
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment