MySQL Bugs: #47905: stored procedures with multiple statements not being logged to slow query log

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

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.

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.

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" )

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.

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.

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

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

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)

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)

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)

Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100224135227-rcqs9pe9b2in80pf) (pib:16)

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.

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.

see bug #53191 for folks having negative Lock_time after a stored routine is called.

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)

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)

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)