MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Kristofer Pettersson Date:June 8 2010 8:58am
Subject:bzr commit into mysql-5.1-bugteam branch (kristofer.pettersson:3419)
Bug#53191
View as plain text  
#At file:///Users/thek/Development/mysql-5.1-bugteam/ based on revid:georgi.kodinov@stripped

 3419 Kristofer Pettersson	2010-06-08
      Bug#53191 Lock_time in slow log is negative when logging stored routines
      
      Logging slow stored procedures caused the slow log to write 
      very large lock times. The lock times was a result of a 
      negative number being cast to an unsigned integer.
      The reason the lock time appeard negative was because 
      one of the measurements points was reset after execution
      causing it to change order with the start time of the 
      statement.
            
      This bug is related to bug 47905 which in turn was 
      introduced because of a joint fix for 12480,12481,12482 and 11587.
      
      The fix is to only reset the start_time before any statement
      execution in a SP while not resetting start_utime or
      utime_after_lock which are used for measuring the 
      performance of the SP. Start_time is used to set the
      timestamp on the replication event which controlls how
      the slave interprets time functions like NOW().

    modified:
      mysql-test/suite/sys_vars/r/slow_query_log_func.result
      mysql-test/suite/sys_vars/t/slow_query_log_func.test
      sql/sp_head.cc
=== modified file 'mysql-test/suite/sys_vars/r/slow_query_log_func.result'
--- a/mysql-test/suite/sys_vars/r/slow_query_log_func.result	2010-02-11 20:10:13 +0000
+++ b/mysql-test/suite/sys_vars/r/slow_query_log_func.result	2010-06-08 08:58:19 +0000
@@ -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;

=== modified file 'mysql-test/suite/sys_vars/t/slow_query_log_func.test'
--- a/mysql-test/suite/sys_vars/t/slow_query_log_func.test	2010-02-11 20:10:13 +0000
+++ b/mysql-test/suite/sys_vars/t/slow_query_log_func.test	2010-06-08 08:58:19 +0000
@@ -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;
 

=== modified file 'sql/sp_head.cc'
--- a/sql/sp_head.cc	2010-04-01 13:15:22 +0000
+++ b/sql/sp_head.cc	2010-06-08 08:58:19 +0000
@@ -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, Lis
 {
   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, Lis
 
   delete nctx;
   thd->spcont= save_spcont;
-  thd->utime_after_lock= utime_before_sp_exec;
-
   DBUG_RETURN(err_status);
 }
 


Attachment: [text/bzr-bundle]
Thread
bzr commit into mysql-5.1-bugteam branch (kristofer.pettersson:3419)Bug#53191Kristofer Pettersson8 Jun