diff --git a/mysql-test/suite/sys_vars/r/slow_query_log_func.result b/mysql-test/suite/sys_vars/r/slow_query_log_func.result index eb7efe4a004..fb650399597 100644 --- a/mysql-test/suite/sys_vars/r/slow_query_log_func.result +++ b/mysql-test/suite/sys_vars/r/slow_query_log_func.result @@ -36,5 +36,78 @@ SELECT count(*) > 0 FROM mysql.slow_log; count(*) > 0 1 DROP PROCEDURE p_test; +Bug53191 Lock_time in slow log is negative when logging stored routines +TRUNCATE mysql.slow_log; +CREATE TABLE t1 (c0 INT PRIMARY KEY AUTO_INCREMENT, c1 TIMESTAMP, c2 TIMESTAMP); +CREATE FUNCTION f_slow_now() RETURNS TIMESTAMP +BEGIN +DO SLEEP(2); +RETURN NOW(); +END// +CREATE FUNCTION f_slow_current_time() RETURNS TIME +BEGIN +DO SLEEP(2); +RETURN CURRENT_TIME(); +END +// +INSERT INTO t1 (c1,c2) VALUES (now(), f_slow_now())// +CREATE TRIGGER tf_before BEFORE INSERT ON t1 +FOR EACH ROW BEGIN +SET new.c2 = f_slow_now(); +END// +CREATE PROCEDURE p1() +BEGIN +INSERT INTO t1 (c1,c2) values (now(),now()); +DO SLEEP(2); +INSERT INTO t1 (c1,c2) values (now(),now()); +end// +INSERT INTO t1 (c1,c2) VALUES (now(), now()); +CALL p1(); +SELECT c1-c2 FROM t1; +c1-c2 +0 +0 +0 +0 +*** There shouldn't less than 1 s difference between each row +SELECT t1.c1-self.c1 > 1 FROM t1, t1 as self WHERE t1.c0=self.c0+1 ORDER BY t1.c0; +t1.c1-self.c1 > 1 +1 +1 +1 +DROP TRIGGER tf_before; +DROP FUNCTION f_slow_now; +DROP FUNCTION f_slow_current_time; +DROP TABLE t1; +DROP TABLE IF EXISTS t1; +Warnings: +Note 1051 Unknown table 't1' +CREATE TABLE t1(c1 INT) ENGINE=MyISAM; +DROP PROCEDURE IF EXISTS p1; +CREATE PROCEDURE p1() +BEGIN +INSERT INTO t1 VALUES (1); +SELECT COUNT(*) FROM t1 WHERE c1= 1; +UPDATE t1 SET c1=c1*2; +END| +Connection 2 +LOCK TABLE t1 WRITE; +Back to default connection +CALL p1(); +Wait three seconds and unlock the table +UNLOCK TABLES; +COUNT(*) +1 +Slow log: +**** 1 == we have slow log entries +SELECT count(*) > 0 FROM mysql.slow_log; +count(*) > 0 +1 +**** 0 == None of the entries have a lock time greater than 10 s +SELECT count(*) FROM mysql.slow_log WHERE lock_time > 10; +count(*) +0 +DROP TABLE t1; +DROP PROCEDURE p1; SET @@global.log_output = @global_log_output; SET @global.slow_query_log = @global_slow_query_log; diff --git a/mysql-test/suite/sys_vars/t/slow_query_log_func.test b/mysql-test/suite/sys_vars/t/slow_query_log_func.test index 250d5210c46..dd202ec20ff 100644 --- a/mysql-test/suite/sys_vars/t/slow_query_log_func.test +++ b/mysql-test/suite/sys_vars/t/slow_query_log_func.test @@ -51,8 +51,93 @@ CALL p_test(); SELECT count(*) > 0 FROM mysql.slow_log; DROP PROCEDURE p_test; +#============================================================================== +--echo Bug53191 Lock_time in slow log is negative when logging stored routines +#============================================================================== +TRUNCATE mysql.slow_log; +connect (con2,localhost,root,,); +connection default; -#restore +CREATE TABLE t1 (c0 INT PRIMARY KEY AUTO_INCREMENT, c1 TIMESTAMP, c2 TIMESTAMP); +delimiter //; +CREATE FUNCTION f_slow_now() RETURNS TIMESTAMP +BEGIN + DO SLEEP(2); + RETURN NOW(); +END// + +CREATE FUNCTION f_slow_current_time() RETURNS TIME +BEGIN + DO SLEEP(2); + RETURN CURRENT_TIME(); +END +// + +INSERT INTO t1 (c1,c2) VALUES (now(), f_slow_now())// + +CREATE TRIGGER tf_before BEFORE INSERT ON t1 +FOR EACH ROW BEGIN + SET new.c2 = f_slow_now(); +END// + +CREATE PROCEDURE p1() +BEGIN + INSERT INTO t1 (c1,c2) values (now(),now()); + DO SLEEP(2); + INSERT INTO t1 (c1,c2) values (now(),now()); +end// + +delimiter ;// + +INSERT INTO t1 (c1,c2) VALUES (now(), now()); +CALL p1(); + +SELECT c1-c2 FROM t1; +--echo *** There shouldn't less than 1 s difference between each row +SELECT t1.c1-self.c1 > 1 FROM t1, t1 as self WHERE t1.c0=self.c0+1 ORDER BY t1.c0; + +DROP TRIGGER tf_before; +DROP FUNCTION f_slow_now; +DROP FUNCTION f_slow_current_time; +DROP TABLE t1; + +DROP TABLE IF EXISTS t1; +CREATE TABLE t1(c1 INT) ENGINE=MyISAM; +DROP PROCEDURE IF EXISTS p1; +delimiter |; +CREATE PROCEDURE p1() +BEGIN + INSERT INTO t1 VALUES (1); + SELECT COUNT(*) FROM t1 WHERE c1= 1; + UPDATE t1 SET c1=c1*2; +END| +delimiter ;| + +--echo Connection 2 +connection con2; +LOCK TABLE t1 WRITE; + +--echo Back to default connection +connection default; +send CALL p1(); + +--echo Wait three seconds and unlock the table +connection con2; +sleep 3; +UNLOCK TABLES; +connection default; +reap; +--echo Slow log: +--echo **** 1 == we have slow log entries +SELECT count(*) > 0 FROM mysql.slow_log; +--echo **** 0 == None of the entries have a lock time greater than 10 s +SELECT count(*) FROM mysql.slow_log WHERE lock_time > 10; +disconnect con2; +DROP TABLE t1; +DROP PROCEDURE p1; + + +#================================================================== Restore SET @@global.log_output = @global_log_output; SET @global.slow_query_log = @global_slow_query_log; diff --git a/sql/sp_head.cc b/sql/sp_head.cc index cadda38053c..66d5eff5112 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -34,6 +34,36 @@ extern "C" uchar *sp_table_key(const uchar *ptr, size_t *plen, my_bool first); +/** + Helper function which operates on a THD object to set the query start_time to + the current time. + + @param[in, out] thd The session object + +*/ + +static void reset_start_time_for_sp(THD *thd) +{ + /* + Do nothing if the context is a trigger or function because time should be + constant during the execution of those. + */ + if (!thd->in_sub_stmt) + { + /* + First investigate if there is a cached time stamp + */ + if (thd->user_time) + { + thd->start_time= thd->user_time; + } + else + { + my_micro_time_and_time(&thd->start_time); + } + } +} + Item_result sp_map_result_type(enum enum_field_types type) { @@ -1225,10 +1255,13 @@ sp_head::execute(THD *thd) DBUG_PRINT("execute", ("Instruction %u", ip)); - /* Don't change NOW() in FUNCTION or TRIGGER */ - if (!thd->in_sub_stmt) - thd->set_time(); // Make current_time() et al work - + /* + We need to reset start_time to allow for time to flow inside a stored + procedure. This is only done for SP since time is suppose to be constant + during execution of triggers and functions. + */ + reset_start_time_for_sp(thd); + /* We have to set thd->stmt_arena before executing the instruction to store in the instruction free_list all new items, created @@ -1840,8 +1873,6 @@ sp_head::execute_procedure(THD *thd, List *args) { bool err_status= FALSE; uint params = m_pcont->context_var_count(); - /* Query start time may be reset in a multi-stmt SP; keep this for later. */ - ulonglong utime_before_sp_exec= thd->utime_after_lock; sp_rcontext *save_spcont, *octx; sp_rcontext *nctx = NULL; bool save_enable_slow_log= false; @@ -2034,8 +2065,6 @@ sp_head::execute_procedure(THD *thd, List *args) delete nctx; thd->spcont= save_spcont; - thd->utime_after_lock= utime_before_sp_exec; - DBUG_RETURN(err_status); }