From f4a16558c81af480d1cd9e09bd3965e598c561ac Mon Sep 17 00:00:00 2001
From: Staale Smedseng <staale.smedseng@sun.com>
Date: Thu, 11 Feb 2010 21:10:13 +0100
Subject: [PATCH] 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().
---
 .../sys_vars/r/slow_query_log_func.result     | 16 ++++++++++++++
 .../suite/sys_vars/t/slow_query_log_func.test | 21 +++++++++++++++++++
 sql/sp_head.cc                                |  3 +++
 3 files changed, 40 insertions(+)

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 d5485e2e6d7..eb7efe4a004 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
@@ -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;
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 d2653f89de4..250d5210c46 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
@@ -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;
diff --git a/sql/sp_head.cc b/sql/sp_head.cc
index 45cb4eebb09..8a626cabd90 100644
--- a/sql/sp_head.cc
+++ b/sql/sp_head.cc
@@ -1848,6 +1848,8 @@ sp_head::execute_procedure(THD *thd, List<Item> *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;
@@ -2040,6 +2042,7 @@ sp_head::execute_procedure(THD *thd, List<Item> *args)
 
   delete nctx;
   thd->spcont= save_spcont;
+  thd->utime_after_lock= utime_before_sp_exec;
 
   DBUG_RETURN(err_status);
 }