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

Proposed by Sergei Glushchenko on 2014-11-10
Status: Merged
Approved by: Laurynas Biveinis on 2014-12-02
Approved revision: 699
Merged at revision: 718
Proposed branch: lp:~sergei.glushchenko/percona-server/5.5-slow-log-stored-procs
Merge into: lp:percona-server/5.5
Diff against target: 277 lines (+112/-26)
6 files modified
mysql-test/r/percona_log_slow_sp_statements.result (+46/-10)
mysql-test/t/percona_log_slow_sp_statements.test (+33/-5)
sql/log.cc (+9/-0)
sql/sp_head.cc (+0/-8)
sql/sp_rcontext.h (+2/-3)
sql/sql_parse.cc (+22/-0)
To merge this branch: bzr merge lp:~sergei.glushchenko/percona-server/5.5-slow-log-stored-procs
Reviewer Review Type Date Requested Status
Laurynas Biveinis (community) 2014-11-10 Approve on 2014-12-02
Review via email: mp+241224@code.launchpad.net

Description of the change

    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/

To post a comment you must log in.

    - 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

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.

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/

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'mysql-test/r/percona_log_slow_sp_statements.result'
2--- mysql-test/r/percona_log_slow_sp_statements.result 2013-02-11 08:09:00 +0000
3+++ mysql-test/r/percona_log_slow_sp_statements.result 2014-12-01 21:16:02 +0000
4@@ -1,28 +1,64 @@
5-DROP PROCEDURE IF EXISTS test_f;
6+DROP PROCEDURE IF EXISTS test_outer;
7+DROP PROCEDURE IF EXISTS test_inner;
8 SET SESSION min_examined_row_limit=0;
9 SET SESSION long_query_time=0;
10 SET SESSION query_cache_type=0;
11-CREATE PROCEDURE test_f()
12+CREATE PROCEDURE test_inner()
13+BEGIN
14+SELECT 2;
15+END^
16+CREATE PROCEDURE test_outer()
17 BEGIN
18 SELECT 1;
19+CALL test_inner();
20 END^
21+PREPARE stmt FROM "CALL test_outer()";
22 SET GLOBAL log_slow_sp_statements=ON;
23 [log_start.inc] percona.slow_extended.sp1
24-CALL test_f();
25-1
26-1
27+CALL test_outer();
28+1
29+1
30+2
31+2
32+EXECUTE stmt;
33+1
34+1
35+2
36+2
37 [log_stop.inc] percona.slow_extended.sp1
38 [log_grep.inc] file: percona.slow_extended.sp1 pattern: SELECT 1;
39-[log_grep.inc] lines: 1
40+[log_grep.inc] lines: 2
41+[log_grep.inc] file: percona.slow_extended.sp1 pattern: SELECT 2;
42+[log_grep.inc] lines: 2
43+[log_grep.inc] file: percona.slow_extended.sp1 pattern: CALL test_
44+[log_grep.inc] lines: 0
45+[log_grep.inc] file: percona.slow_extended.sp1 pattern: # Stored routine: test.test_outer
46+[log_grep.inc] lines: 2
47+[log_grep.inc] file: percona.slow_extended.sp1 pattern: # Stored routine: test.test_inner
48+[log_grep.inc] lines: 2
49 SET GLOBAL log_slow_sp_statements=OFF;
50 [log_start.inc] percona.slow_extended.sp2
51-CALL test_f();
52-1
53-1
54+CALL test_outer();
55+1
56+1
57+2
58+2
59+EXECUTE stmt;
60+1
61+1
62+2
63+2
64 [log_stop.inc] percona.slow_extended.sp2
65 [log_grep.inc] file: percona.slow_extended.sp2 pattern: SELECT 1;
66 [log_grep.inc] lines: 0
67-DROP PROCEDURE test_f;
68+[log_grep.inc] file: percona.slow_extended.sp2 pattern: SELECT 2;
69+[log_grep.inc] lines: 0
70+[log_grep.inc] file: percona.slow_extended.sp2 pattern: CALL test_
71+[log_grep.inc] lines: 2
72+[log_grep.inc] file: percona.slow_extended.sp2 pattern: # Stored routine: test.test_
73+[log_grep.inc] lines: 0
74+DROP PROCEDURE test_outer;
75+DROP PROCEDURE test_inner;
76 SET GLOBAL log_slow_sp_statements=default;
77 SET SESSION long_query_time=default;
78 SET SESSION min_examined_row_limit=default;
79
80=== modified file 'mysql-test/t/percona_log_slow_sp_statements.test'
81--- mysql-test/t/percona_log_slow_sp_statements.test 2013-02-11 08:09:00 +0000
82+++ mysql-test/t/percona_log_slow_sp_statements.test 2014-12-01 21:16:02 +0000
83@@ -2,7 +2,8 @@
84 # Test slow-logging of statements in stored procedures
85 #
86 --disable_warnings
87-DROP PROCEDURE IF EXISTS test_f;
88+DROP PROCEDURE IF EXISTS test_outer;
89+DROP PROCEDURE IF EXISTS test_inner;
90 --enable_warnings
91
92 SET SESSION min_examined_row_limit=0;
93@@ -10,29 +11,56 @@
94 SET SESSION query_cache_type=0;
95
96 delimiter ^;
97-CREATE PROCEDURE test_f()
98+CREATE PROCEDURE test_inner()
99+BEGIN
100+ SELECT 2;
101+END^
102+delimiter ;^
103+
104+delimiter ^;
105+CREATE PROCEDURE test_outer()
106 BEGIN
107 SELECT 1;
108+ CALL test_inner();
109 END^
110 delimiter ;^
111
112+PREPARE stmt FROM "CALL test_outer()";
113+
114 SET GLOBAL log_slow_sp_statements=ON;
115 --let log_file=percona.slow_extended.sp1
116 --source include/log_start.inc
117-CALL test_f();
118+CALL test_outer();
119+EXECUTE stmt;
120 --source include/log_stop.inc
121 --let grep_pattern=SELECT 1;
122 --source include/log_grep.inc
123+--let grep_pattern=SELECT 2;
124+--source include/log_grep.inc
125+--let grep_pattern=CALL test_
126+--source include/log_grep.inc
127+--let grep_pattern=# Stored routine: test.test_outer
128+--source include/log_grep.inc
129+--let grep_pattern=# Stored routine: test.test_inner
130+--source include/log_grep.inc
131
132 SET GLOBAL log_slow_sp_statements=OFF;
133 --let log_file=percona.slow_extended.sp2
134 --source include/log_start.inc
135-CALL test_f();
136+CALL test_outer();
137+EXECUTE stmt;
138 --source include/log_stop.inc
139 --let grep_pattern=SELECT 1;
140 --source include/log_grep.inc
141+--let grep_pattern=SELECT 2;
142+--source include/log_grep.inc
143+--let grep_pattern=CALL test_
144+--source include/log_grep.inc
145+--let grep_pattern=# Stored routine: test.test_
146+--source include/log_grep.inc
147
148-DROP PROCEDURE test_f;
149+DROP PROCEDURE test_outer;
150+DROP PROCEDURE test_inner;
151
152 SET GLOBAL log_slow_sp_statements=default;
153 SET SESSION long_query_time=default;
154
155=== modified file 'sql/log.cc'
156--- sql/log.cc 2014-09-24 09:00:06 +0000
157+++ sql/log.cc 2014-12-01 21:16:02 +0000
158@@ -39,6 +39,8 @@
159 #include "rpl_filter.h"
160 #include "rpl_rli.h"
161 #include "sql_audit.h"
162+#include "sp_rcontext.h"
163+#include "sp_head.h"
164
165 #include <my_dir.h>
166 #include <stdarg.h>
167@@ -2828,6 +2830,13 @@
168 if (my_b_write(&log_file, (uchar*) "\n", 1))
169 tmp_errno= errno;
170
171+ if (opt_log_slow_sp_statements &&
172+ thd->spcont &&
173+ my_b_printf(&log_file,
174+ "# Stored routine: %s\n",
175+ thd->spcont->sp->m_qname.str) == (uint) -1)
176+ tmp_errno= errno;
177+
178 #if defined(ENABLED_PROFILING)
179 thd->profiling.print_current(&log_file);
180 #endif
181
182=== modified file 'sql/sp_head.cc'
183--- sql/sp_head.cc 2013-10-22 13:33:14 +0000
184+++ sql/sp_head.cc 2014-12-01 21:16:02 +0000
185@@ -1729,9 +1729,7 @@
186 goto err_with_cleanup;
187 }
188
189-#ifndef DBUG_OFF
190 nctx->sp= this;
191-#endif
192
193 thd->spcont= nctx;
194
195@@ -1855,9 +1853,7 @@
196 */
197 thd->restore_active_arena(&call_arena, &backup_arena);
198
199-#ifndef DBUG_OFF
200 nctx->sp= this;
201-#endif
202
203 /* Pass arguments. */
204 for (arg_no= 0; arg_no < argcount; arg_no++)
205@@ -2063,9 +2059,7 @@
206 DBUG_RETURN(TRUE);
207 }
208
209-#ifndef DBUG_OFF
210 octx->sp= 0;
211-#endif
212 thd->spcont= octx;
213
214 /* set callers_arena to thd, for upper-level function to work */
215@@ -2079,9 +2073,7 @@
216 thd->spcont= save_spcont;
217 DBUG_RETURN(TRUE);
218 }
219-#ifndef DBUG_OFF
220 nctx->sp= this;
221-#endif
222
223 if (params > 0)
224 {
225
226=== modified file 'sql/sp_rcontext.h'
227--- sql/sp_rcontext.h 2013-03-19 12:36:34 +0000
228+++ sql/sp_rcontext.h 2014-12-01 21:16:02 +0000
229@@ -139,13 +139,12 @@
230 */
231 bool end_partial_result_set;
232
233-#ifndef DBUG_OFF
234 /*
235 The routine for which this runtime context is created. Used for checking
236- if correct runtime context is used for variable handling.
237+ if correct runtime context is used for variable handling and for logging
238+ slow statements inside of stored procedure.
239 */
240 sp_head *sp;
241-#endif
242
243 sp_rcontext(sp_pcontext *root_parsing_ctx, Field *return_value_fld,
244 sp_rcontext *prev_runtime_ctx);
245
246=== modified file 'sql/sql_parse.cc'
247--- sql/sql_parse.cc 2014-08-22 09:58:37 +0000
248+++ sql/sql_parse.cc 2014-12-01 21:16:02 +0000
249@@ -1580,6 +1580,28 @@
250 #endif
251
252 /*
253+ Don't log the CALL statement if slow statements logging
254+ inside of stored procedures is enabled.
255+ This code should be run after query_response_time_collect(...)
256+ function to avoid influence on query_response_time_stats logic.
257+ */
258+ if (opt_log_slow_sp_statements &&
259+ thd->lex)
260+ {
261+ if (thd->lex->sql_command == SQLCOM_CALL)
262+ DBUG_VOID_RETURN;
263+ /* Can be prepared CALL statement */
264+ if (thd->lex->sql_command == SQLCOM_EXECUTE)
265+ {
266+ Statement *stmt;
267+ LEX_STRING *name= &thd->lex->prepared_stmt_name;
268+ if ((stmt= thd->stmt_map.find_by_name(name)) != NULL &&
269+ stmt->lex && stmt->lex->sql_command == SQLCOM_CALL)
270+ DBUG_VOID_RETURN;
271+ }
272+ }
273+
274+ /*
275 Low long_query_time value most likely means user is debugging stuff and even
276 though some thread's queries are not supposed to be logged b/c of the rate
277 limit, if one of them takes long enough (>= 1 second) it will be sensible

Subscribers

People subscribed via source and target branches