2 files changed, 159 insertions, 1 deletions
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;
+
+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
+#==================================================================   Restore
 SET @@global.log_output = @global_log_output;
 SET @global.slow_query_log = @global_slow_query_log;