MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Staale Smedseng Date:February 11 2010 8:10pm
Subject:bzr commit into mysql-5.1-bugteam branch (staale.smedseng:3376) Bug#47905
View as plain text  
#At file:///export/home/tmp/ss156133/z/47905-51/ based on revid:martin.hansson@stripped

 3376 Staale Smedseng	2010-02-11
      Bug #47905 stored procedures with conditional statements not
      being logged to slow query log
      
      The problem is that the execution time for a multi-statement
      stored procedure as a whole may not be accurate, and thus not
      be entered into the slow query log even if the total time
      exceeds long_query_time. The reason for this is that
      THD::utime_after_lock used for time calculation may be reset
      at the start of each new statement, possibly leaving the total
      SP execution equal to the time spent executing the last
      statement in the SP.
      
      This patch stores the utime on start of SP execution, and
      restores it on exit of SP execution. A test is added.
     @ mysql-test/suite/sys_vars/r/slow_query_log_func.result
        New test results for #47905.
     @ mysql-test/suite/sys_vars/t/slow_query_log_func.test
        New test case for #47905.
     @ sql/sp_head.cc
        Save and restore the THD::utime_after_lock on entry and 
        exit of execute_procedure().

    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	2009-03-20 17:11:22 +0000
+++ b/mysql-test/suite/sys_vars/r/slow_query_log_func.result	2010-02-11 20:10:13 +0000
@@ -20,5 +20,21 @@ sleep(2)
 SELECT count(*) > 0 FROM mysql.slow_log;
 count(*) > 0
 1
+'Bug#47905 stored procedures not logged correctly to slow query log'
+TRUNCATE mysql.slow_log;
+CREATE PROCEDURE p_test() 
+BEGIN
+select sleep(2);
+select 1;
+END//
+CALL p_test();
+sleep(2)
+0
+1
+1
+SELECT count(*) > 0 FROM mysql.slow_log;
+count(*) > 0
+1
+DROP PROCEDURE p_test;
 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	2009-03-20 17:11:22 +0000
+++ b/mysql-test/suite/sys_vars/t/slow_query_log_func.test	2010-02-11 20:10:13 +0000
@@ -31,6 +31,27 @@ SELECT sleep(2);
 
 SELECT count(*) > 0 FROM mysql.slow_log;
 
+
+#==========================================================================
+--echo 'Bug#47905 stored procedures not logged correctly to slow query log'
+#==========================================================================
+# assumes logging to table turned on with long_query_time=1 as above
+ 
+TRUNCATE mysql.slow_log;
+
+DELIMITER //;
+CREATE PROCEDURE p_test() 
+BEGIN
+   select sleep(2);
+   select 1;
+END//
+DELIMITER ;//
+
+CALL p_test();
+SELECT count(*) > 0 FROM mysql.slow_log;
+DROP PROCEDURE p_test;
+
+
 #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-01-24 07:03:23 +0000
+++ b/sql/sp_head.cc	2010-02-11 20:10:13 +0000
@@ -1848,6 +1848,8 @@ 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;
@@ -2040,6 +2042,7 @@ 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] bzr/staale.smedseng@sun.com-20100211201013-d53lj0ttplw4mx60.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (staale.smedseng:3376) Bug#47905Staale Smedseng11 Feb