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().

1 files changed, 37 insertions, 8 deletions

diff --git a/sql/sp_head.cc b/sql/sp_head.cc
index cadda38053c..66d5eff5112 100644
--- a/sql/sp_head.cc
+++ b/sql/sp_head.cc
@@ -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, 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;
@@ -2034,8 +2065,6 @@ 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);
 }