merge 5.1-bugteam => trunk-merge

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;

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;
 

sql/sp_head.cc

@@ -50,6 +50,32 @@
 
 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)
+{
+  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)
 {
@@ -1240,11 +1266,11 @@ sp_head::execute(THD *thd)
     DBUG_PRINT("execute", ("Instruction %u", ip));
 
     /*
-      Make current_time() et al work. But don't change NOW() in FUNCTION
-      or TRIGGER.
+      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.
     */
-    if (!thd->in_sub_stmt)
-      thd->set_time();
+    reset_start_time_for_sp(thd);
 
     /*
       We have to set thd->stmt_arena before executing the instruction