Bug #47905 stored procedures with multiple statements not being logged to slow query log
Submitted: 7 Oct 2009 23:43 Modified: 18 Jun 2010 2:07
Reporter: Matthew Lord Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.1.39 OS:Any
Assigned to: Staale Smedseng CPU Architecture:Any
Tags: slow query log, stored procedures

[7 Oct 2009 23:43] Matthew Lord
Description:
5.1 does not seem to be logging slow stored procedures to the slow log if the
procedure contains a conditional statement.  It's not logging the "call SPNAME"
SQL statement (nor any individual slow statements within the stored procedure
which is "correct" or rather we expect this much).  If the procedure contains
any conditionals then it seems like slow query logging is completely disabled unless you set long_query_time=0.

How to repeat:
set global slow_query_log=ON;
set session long_query_time=1;
set global long_query_time=1;

delimiter $$

 CREATE PROCEDURE `p_test` ( p1 VARCHAR(20) )
 BEGIN
   select * from information_schema.tables, information_schema.columns;
 END$$

delimiter ;

call p_test( "test1" );

drop procedure p_test;

delimiter $$

 CREATE PROCEDURE `p_test` ( p1 VARCHAR(30) )
 BEGIN

   select * from information_schema.tables, information_schema.columns;

   IF 2 >= 1 THEN
     select "foo";
   END IF;

 END$$

delimiter ;

call p_test( "test2" );

Suggested fix:
We should log these slow procedures or at the very least update the documentation to reflect this limitation.
[8 Oct 2009 0:33] Alexey Kishkin
I changed  select * from information_scheme to select sleep(5) in both procedures in the testcase.

After execution slow log contains:

 Version: 5.1.39 (Source distribution). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 091008 10:19:51
# User@Host: root[root] @ localhost []
# Query_time: 5.000232  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use test;
SET timestamp=1254961191;
call p_test( "test1" );

As far as p_test ("test2") has not appeared in the slow log, I set status as verified.
[8 Oct 2009 2:02] Matthew Lord
Here's another modified test case for those who don't have enough tables for the original test case to take longer than 1 second:

set global slow_query_log=ON;
set session long_query_time=1;
set global long_query_time=1;

delimiter $$

 CREATE PROCEDURE `p_test` ( p1 VARCHAR(20) )
 BEGIN
   select sleep(5);
 END$$

delimiter ;

call p_test( "test1" );

drop procedure p_test;

delimiter $$

 CREATE PROCEDURE `p_test` ( p1 VARCHAR(20) )
 BEGIN

   select sleep(5);

   IF 2 >= 1 THEN
     select "foo";
   END IF;

 END$$

delimiter ;

call p_test( "test2" );

# now tail -20 DATADIR/HOSTNAME-slow.log and you'll see that it only contains
# call p_test( "test1" ) and NOT call p_test( "test2" )
[27 Nov 2009 19:05] MySQL Verification Team
This has nothing to do with conditional statements. I studied a code very carefully and found out that it is about commands. CALL () will log only the time of the last command !!!

So, this procedure:

delimiter $$

 CREATE PROCEDURE `p_test` ( p1 VARCHAR(20) )
 BEGIN

   select sleep(5);

   select "foo";

 END$$

delimiter ;

will NOT go into slow query log, while this procedure:

delimiter $$

 CREATE PROCEDURE `p_test` ( p1 VARCHAR(20) )
 BEGIN

   select "foo";

   select sleep(5);

 END$$

delimiter ;

will be logged into the slow query log.

The reason for this behaviour is that the time for the last lock is the only one taken into account. Every command, however, passes through some functions, including locking tables, which resets the time.

A fix is to save and reset this time after each command. I will come with a fix next week.
[5 Dec 2009 18:51] MySQL Verification Team
This is a patch that fixes a bug:

=== modified file 'sql/sp_head.cc'
--- sql/sp_head.cc      2009-05-30 13:32:28 +0000
+++ sql/sp_head.cc      2009-12-05 18:41:34 +0000
@@ -1845,6 +1845,7 @@
 {
   bool err_status= FALSE;
   uint params = m_pcont->context_var_count();
+  ulonglong save_utime= thd->utime_after_lock;
   sp_rcontext *save_spcont, *octx;
   sp_rcontext *nctx = NULL;
   bool save_enable_slow_log= false;
@@ -2037,6 +2038,7 @@
 
   delete nctx;
   thd->spcont= save_spcont;
+  thd->utime_after_lock= save_utime;
 
   DBUG_RETURN(err_status);
 }

You can use the above test case.
[11 Feb 2010 13:25] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/99937

3375 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 for this is added. Optionally, this may be folded into
      the previous test case in order to save 2 seconds of sleep
      time in the test, if desired.
     @ mysql-test/suite/sys_vars/r/slow_query_log_func.result
        New 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().
[11 Feb 2010 20:10] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/100025

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().
[1 Mar 2010 8:47] Bugs System
Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:joerg@mysql.com-20100212173307-ph563zr4wmoklgwd) (merge vers: 5.1.45) (pib:16)
[2 Mar 2010 14:35] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100302142746-u1gxdf5yk2bjrq3e) (version source revid:alik@sun.com-20100225090938-2j5ybqoau570mytu) (merge vers: 6.0.14-alpha) (pib:16)
[2 Mar 2010 14:40] Bugs System
Pushed into 5.5.3-m2 (revid:alik@sun.com-20100302072233-t3uqgjzdukt1pyhe) (version source revid:alexey.kopytov@sun.com-20100221213311-xf5nyv391dsw9v6j) (merge vers: 5.5.2-m2) (pib:16)
[2 Mar 2010 14:45] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100224135227-rcqs9pe9b2in80pf) (pib:16)
[7 Mar 2010 20:22] Paul Dubois
Noted in 5.1.45, 5.5.3, 6.0.14 changelogs.

Slow CALL statements were not always logged to the slow query log
because execution time for multiple-statement stored procedures was
assessed incorrectly.
[5 May 2010 21:12] Zhang Lu
Should you restore the saved time to thd->start_utime?
with the current patch, the Query Time in slow log still only shows the execution time for the last statement in stored procedure. If thd->start_utime can be restored after execution, the Query Time value in slow log is true stp exe time which I think is what everybody wants.
[13 May 2010 7:04] MySQL Verification Team
see bug #53191 for folks having negative Lock_time after a stored routine is called.
[17 Jun 2010 12:20] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:08] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)
[17 Jun 2010 13:48] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)