Merge lp:~sergei.glushchenko/percona-server/5.5-slow-log-stored-procs into lp:percona-server/5.5

[Sergei Glushchenko]

    Implementation of log-slow-sp-statements blueprint

    When log_slow_sp_statement is ON
    - Make an entry to slow-log for each query in stored procedures.
    - Don't make an entry to slow-log for the CALL itself, because that
      would count the time twice and skew reports.
    - Slow-log entries are annotated with the stored procedure in
      which it ran.

There is also issue 43131. Customer wants CALL statement not showed in slow log even if it takes long to execute, however individual queries inside stored procedure should be logged if they take long.

The part of this blueprint regarding bug #719386 has already been fixed.

http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1065/

[Laurynas Biveinis (laurynas-biveinis)]

    - How are statements referencing procedure args logged? With var
      names, values, or something else?
    - Same question for the combination of stored procedures and
      prepared statements (i.e. case 1: PREPARE s CALL p(@foo, 2);
      EXECUTE s; case 2: PREPARE s CALL p(?, ?); EXECUTE s USING 1,
      @foo; maybe case 3: PROCEDURE foo BEGIN EXECUTE bar;
    - In the case of non-trivial answers, the above needs MTR
      testing.

review: Needs Information

[Sergei Glushchenko (sergei.glushchenko)]

In all cases statement will look like

SELECT NAME_CONST('a',101), NAME_CONST('b',102);

But prepared CALL statement will be logged into slow log because it is SQLCOM_EXECUTE, not the SQLCOM_CALL. Not sure how to differentiate this case yet.

[Sergei Glushchenko (sergei.glushchenko)]

I made changes needed to recognize prepared statements which are CALL statements. Answer to the question posted in prev comment. Jenkins:
http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1070/

[Laurynas Biveinis (laurynas-biveinis)]

review: Approve

=== modified file 'mysql-test/r/percona_log_slow_sp_statements.result'
--- mysql-test/r/percona_log_slow_sp_statements.result	2013-02-11 08:09:00 +0000
+++ mysql-test/r/percona_log_slow_sp_statements.result	2014-12-01 21:16:02 +0000
@@ -1,28 +1,64 @@
-DROP PROCEDURE IF EXISTS test_f;
+DROP PROCEDURE IF EXISTS test_outer;
+DROP PROCEDURE IF EXISTS test_inner;
 SET SESSION min_examined_row_limit=0;
 SET SESSION long_query_time=0;
 SET SESSION query_cache_type=0;
-CREATE PROCEDURE test_f()
+CREATE PROCEDURE test_inner()
+BEGIN
+SELECT 2;
+END^
+CREATE PROCEDURE test_outer()
 BEGIN
 SELECT 1;
+CALL test_inner();
 END^
+PREPARE stmt FROM "CALL test_outer()";
 SET GLOBAL log_slow_sp_statements=ON;
 [log_start.inc] percona.slow_extended.sp1
-CALL test_f();
-1
-1
+CALL test_outer();
+1
+1
+2
+2
+EXECUTE stmt;
+1
+1
+2
+2
 [log_stop.inc] percona.slow_extended.sp1
 [log_grep.inc] file: percona.slow_extended.sp1 pattern: SELECT 1;
-[log_grep.inc] lines:   1
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.sp1 pattern: SELECT 2;
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.sp1 pattern: CALL test_
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.sp1 pattern: # Stored routine: test.test_outer
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.sp1 pattern: # Stored routine: test.test_inner
+[log_grep.inc] lines:   2
 SET GLOBAL log_slow_sp_statements=OFF;
 [log_start.inc] percona.slow_extended.sp2
-CALL test_f();
-1
-1
+CALL test_outer();
+1
+1
+2
+2
+EXECUTE stmt;
+1
+1
+2
+2
 [log_stop.inc] percona.slow_extended.sp2
 [log_grep.inc] file: percona.slow_extended.sp2 pattern: SELECT 1;
 [log_grep.inc] lines:   0
-DROP PROCEDURE test_f;
+[log_grep.inc] file: percona.slow_extended.sp2 pattern: SELECT 2;
+[log_grep.inc] lines:   0
+[log_grep.inc] file: percona.slow_extended.sp2 pattern: CALL test_
+[log_grep.inc] lines:   2
+[log_grep.inc] file: percona.slow_extended.sp2 pattern: # Stored routine: test.test_
+[log_grep.inc] lines:   0
+DROP PROCEDURE test_outer;
+DROP PROCEDURE test_inner;
 SET GLOBAL log_slow_sp_statements=default;
 SET SESSION long_query_time=default;
 SET SESSION min_examined_row_limit=default;

=== modified file 'mysql-test/t/percona_log_slow_sp_statements.test'
--- mysql-test/t/percona_log_slow_sp_statements.test	2013-02-11 08:09:00 +0000
+++ mysql-test/t/percona_log_slow_sp_statements.test	2014-12-01 21:16:02 +0000
@@ -2,7 +2,8 @@
 # Test slow-logging of statements in stored procedures
 #
 --disable_warnings
-DROP PROCEDURE IF EXISTS test_f;
+DROP PROCEDURE IF EXISTS test_outer;
+DROP PROCEDURE IF EXISTS test_inner;
 --enable_warnings
 
 SET SESSION min_examined_row_limit=0;
@@ -10,29 +11,56 @@
 SET SESSION query_cache_type=0;
 
 delimiter ^;
-CREATE PROCEDURE test_f()
+CREATE PROCEDURE test_inner()
+BEGIN
+   SELECT 2;
+END^
+delimiter ;^
+
+delimiter ^;
+CREATE PROCEDURE test_outer()
 BEGIN
    SELECT 1;
+   CALL test_inner();
 END^
 delimiter ;^
 
+PREPARE stmt FROM "CALL test_outer()";
+
 SET GLOBAL log_slow_sp_statements=ON;
 --let log_file=percona.slow_extended.sp1
 --source include/log_start.inc
-CALL test_f();
+CALL test_outer();
+EXECUTE stmt;
 --source include/log_stop.inc
 --let grep_pattern=SELECT 1;
 --source include/log_grep.inc
+--let grep_pattern=SELECT 2;
+--source include/log_grep.inc
+--let grep_pattern=CALL test_
+--source include/log_grep.inc
+--let grep_pattern=# Stored routine: test.test_outer
+--source include/log_grep.inc
+--let grep_pattern=# Stored routine: test.test_inner
+--source include/log_grep.inc
 
 SET GLOBAL log_slow_sp_statements=OFF;
 --let log_file=percona.slow_extended.sp2
 --source include/log_start.inc
-CALL test_f();
+CALL test_outer();
+EXECUTE stmt;
 --source include/log_stop.inc
 --let grep_pattern=SELECT 1;
 --source include/log_grep.inc
+--let grep_pattern=SELECT 2;
+--source include/log_grep.inc
+--let grep_pattern=CALL test_
+--source include/log_grep.inc
+--let grep_pattern=# Stored routine: test.test_
+--source include/log_grep.inc
 
-DROP PROCEDURE test_f;
+DROP PROCEDURE test_outer;
+DROP PROCEDURE test_inner;
 
 SET GLOBAL log_slow_sp_statements=default;
 SET SESSION long_query_time=default;

=== modified file 'sql/log.cc'
--- sql/log.cc	2014-09-24 09:00:06 +0000
+++ sql/log.cc	2014-12-01 21:16:02 +0000
@@ -39,6 +39,8 @@
 #include "rpl_filter.h"
 #include "rpl_rli.h"
 #include "sql_audit.h"
+#include "sp_rcontext.h"
+#include "sp_head.h"
 
 #include <my_dir.h>
 #include <stdarg.h>
@@ -2828,6 +2830,13 @@
     if (my_b_write(&log_file, (uchar*) "\n", 1))
         tmp_errno= errno;
 
+    if (opt_log_slow_sp_statements &&
+        thd->spcont &&
+        my_b_printf(&log_file,
+                    "# Stored routine: %s\n",
+                    thd->spcont->sp->m_qname.str) == (uint) -1)
+      tmp_errno= errno;
+
 #if defined(ENABLED_PROFILING)
     thd->profiling.print_current(&log_file);
 #endif

=== modified file 'sql/sp_head.cc'
--- sql/sp_head.cc	2013-10-22 13:33:14 +0000
+++ sql/sp_head.cc	2014-12-01 21:16:02 +0000
@@ -1729,9 +1729,7 @@
     goto err_with_cleanup;
   }
 
-#ifndef DBUG_OFF
   nctx->sp= this;
-#endif
 
   thd->spcont= nctx;
 
@@ -1855,9 +1853,7 @@
   */
   thd->restore_active_arena(&call_arena, &backup_arena);
 
-#ifndef DBUG_OFF
   nctx->sp= this;
-#endif
 
   /* Pass arguments. */
   for (arg_no= 0; arg_no < argcount; arg_no++)
@@ -2063,9 +2059,7 @@
       DBUG_RETURN(TRUE);
     }
 
-#ifndef DBUG_OFF
     octx->sp= 0;
-#endif
     thd->spcont= octx;
 
     /* set callers_arena to thd, for upper-level function to work */
@@ -2079,9 +2073,7 @@
     thd->spcont= save_spcont;
     DBUG_RETURN(TRUE);
   }
-#ifndef DBUG_OFF
   nctx->sp= this;
-#endif
 
   if (params > 0)
   {

=== modified file 'sql/sp_rcontext.h'
--- sql/sp_rcontext.h	2013-03-19 12:36:34 +0000
+++ sql/sp_rcontext.h	2014-12-01 21:16:02 +0000
@@ -139,13 +139,12 @@
   */
   bool end_partial_result_set;
 
-#ifndef DBUG_OFF
   /*
     The routine for which this runtime context is created. Used for checking
-    if correct runtime context is used for variable handling.
+    if correct runtime context is used for variable handling and for logging
+    slow statements inside of stored procedure.
   */
   sp_head *sp;
-#endif
 
   sp_rcontext(sp_pcontext *root_parsing_ctx, Field *return_value_fld,
               sp_rcontext *prev_runtime_ctx);

=== modified file 'sql/sql_parse.cc'
--- sql/sql_parse.cc	2014-08-22 09:58:37 +0000
+++ sql/sql_parse.cc	2014-12-01 21:16:02 +0000
@@ -1580,6 +1580,28 @@
 #endif
 
   /*
+    Don't log the CALL statement if slow statements logging
+    inside of stored procedures is enabled.
+    This code should be run after query_response_time_collect(...)
+    function to avoid influence on query_response_time_stats logic.
+  */
+  if (opt_log_slow_sp_statements &&
+      thd->lex)
+  {
+    if (thd->lex->sql_command == SQLCOM_CALL)
+      DBUG_VOID_RETURN;
+    /* Can be prepared CALL statement */
+    if (thd->lex->sql_command == SQLCOM_EXECUTE)
+    {
+      Statement *stmt;
+      LEX_STRING *name= &thd->lex->prepared_stmt_name;
+      if ((stmt= thd->stmt_map.find_by_name(name)) != NULL &&
+          stmt->lex && stmt->lex->sql_command == SQLCOM_CALL)
+          DBUG_VOID_RETURN;
+    }
+  }
+
+  /*
     Low long_query_time value most likely means user is debugging stuff and even
     though some thread's queries are not supposed to be logged b/c of the rate
     limit, if one of them takes long enough (>= 1 second) it will be sensible