Below is the list of changes that have just been committed into a local
5.1 repository of andrey. When andrey does a push these changes will
be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html
ChangeSet
1.2204 06/03/01 02:34:22 andrey@lmy004. +8 -0
fix for bug #16426
Events: Event-caused statements don't appear in the slow query log
WL#1034
mysql-test/t/events_slow_query.test
1.1 06/03/01 02:34:07 andrey@lmy004. +62 -0
mysql-test/t/events_slow_query-master.opt
1.1 06/03/01 02:34:07 andrey@lmy004. +1 -0
mysql-test/t/events_slow_query.test
1.0 06/03/01 02:34:07 andrey@lmy004. +0 -0
BitKeeper file /work/mysql-5.1-bug17494/mysql-test/t/events_slow_query.test
mysql-test/t/events_slow_query-master.opt
1.0 06/03/01 02:34:07 andrey@lmy004. +0 -0
BitKeeper file /work/mysql-5.1-bug17494/mysql-test/t/events_slow_query-master.opt
mysql-test/r/events_slow_query.result
1.1 06/03/01 02:34:06 andrey@lmy004. +56 -0
sql/sql_parse.cc
1.526 06/03/01 02:34:06 andrey@lmy004. +2 -0
let us see in the the trace log
sql/sp_head.h
1.81 06/03/01 02:34:06 andrey@lmy004. +2 -1
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/sp_head.cc
1.208 06/03/01 02:34:06 andrey@lmy004. +13 -2
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/event_timed.cc
1.43 06/03/01 02:34:06 andrey@lmy004. +2 -0
enable slow logging for the anonymous SP
sql/event_executor.cc
1.40 06/03/01 02:34:06 andrey@lmy004. +2 -1
enable slow logging
mysql-test/r/events_slow_query.result
1.0 06/03/01 02:34:06 andrey@lmy004. +0 -0
BitKeeper file /work/mysql-5.1-bug17494/mysql-test/r/events_slow_query.result
# This is a BitKeeper patch. What follows are the unified diffs for the
# set of deltas contained in the patch. The rest of the patch, the part
# that BitKeeper cares about, is below these diffs.
# User: andrey
# Host: lmy004.
# Root: /work/mysql-5.1-bug17494
--- 1.525/sql/sql_parse.cc 2006-02-27 16:58:32 +01:00
+++ 1.526/sql/sql_parse.cc 2006-03-01 02:34:06 +01:00
@@ -2111,6 +2111,7 @@ bool dispatch_command(enum enum_server_c
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;
}
--- New file ---
+++ mysql-test/r/events_slow_query.result 06/03/01 02:34:06
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;
--- New file ---
+++ mysql-test/t/events_slow_query-master.opt 06/03/01 02:34:07
--log-slow-queries
--- New file ---
+++ mysql-test/t/events_slow_query.test 06/03/01 02:34:07
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;
--- 1.39/sql/event_executor.cc 2006-02-28 20:32:30 +01:00
+++ 1.40/sql/event_executor.cc 2006-03-01 02:34:06 +01:00
@@ -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]",
--- 1.42/sql/event_timed.cc 2006-02-28 20:32:31 +01:00
+++ 1.43/sql/event_timed.cc 2006-03-01 02:34:06 +01:00
@@ -1162,6 +1162,8 @@ Event_timed::execute(THD *thd, 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
--- 1.207/sql/sp_head.cc 2006-02-25 22:22:05 +01:00
+++ 1.208/sql/sp_head.cc 2006-03-01 02:34:06 +01:00
@@ -1412,6 +1412,7 @@ sp_head::execute_procedure(THD *thd, Lis
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, Lis
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 *n
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
--- 1.80/sql/sp_head.h 2006-02-09 11:34:35 +01:00
+++ 1.81/sql/sp_head.h 2006-03-01 02:34:06 +01:00
@@ -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 */
| Thread |
|---|
| • bk commit into 5.1 tree (andrey:1.2204) BUG#16426 | ahristov | 1 Mar |
