Improve slow-log reporting for queries in stored procs

Registered by Bill Karwin on 2011-06-21

If log_slow_sp_statements=1 and slow_query_log=1:

- Make an entry to slow-log for each query in stored procedures.
- Count query times individually for each query in stored procedures, not cumulative time (cf. bug #719386).
- 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 should be annotated with the stored procedure in which it ran. This allows a mk-query-digest event to gather the SP/SF names for grouping, filtering, etc.

Example:

# User@Host: [root] @ localhost []
# Thread_id: 1 Schema: xxx Last_errno: 0 Killed: 0
. . .other lines...
# Stored_routine: <routine-name>

If log_slow_sp_statements=0 and slow_query_log=1:

- Make an entry to slow-log for a CALL statement.
- Report the time for the CALL statement as the total execution time of the CALL including all its statements.
- Do not make entries for individual statements run in SP/SF.

Blueprint information

Status:
Complete
Approver:
Stewart Smith
Priority:
Medium
Drafter:
Bill Karwin
Direction:
Approved
Assignee:
Sergei Glushchenko
Definition:
Approved
Series goal:
Accepted for 5.5
Implementation:
Implemented
Milestone target:
milestone icon 5.5.41-37.0
Started by
Laurynas Biveinis on 2014-11-13
Completed by
Laurynas Biveinis on 2014-12-02

Whiteboard

Following is done:

    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.

===============

Marcos on 2014-06-18: If log_slow_sp_statements=-1 and slow_query_log=1 then do NOT make an entry to slow-log for CALL statements.

===============

(2012-05-15 10:47:59) KAlexey: vlesin: so how do you propose to solve this problem for query_response_time? we can only count individual statements in a stored routine, rather than the CALL statement for query_response_time, but...

(2012-05-15 10:48:40) KAlexey: I see no way to annotate statements with a stored routine name like in the slow query log, because there's no statements per se in query_response_time, it's an aggregate table

(2012-05-15 10:51:56) vlesin: KAlexey: Yes. The first I propose count total execution time in SP per statement but not cumulatively (see bug #999309). The second I propose don't count "CALL" statement at all, count only statements inside SP.

(2012-05-15 10:55:21) KAlexey: the purpose of query_response_time is to get a big picture of what query execution times look like. so I agree, let's fix bug #999309 by only counting individual statements inside a stored routine

(2012-05-15 10:56:12) KAlexey: which actually brings up an interesting question regarding both the log-slow-sp-statements BP and bug #999309

(2012-05-15 10:56:32) KAlexey: in case of stored procedures, just ignore CALL statements

(2012-05-15 10:57:02) KAlexey: but what about stored functions?

(2012-05-15 10:57:53) KAlexey: as in, should slow query log, for example, count only time spent in a query itself but exclude time spent in a stored function?

(2012-05-15 11:00:47) KAlexey: vlesin: does that make sense? E.g. you have SELECT * FROM t1 WHERE a = func(a);

(2012-05-15 11:01:17) KAlexey: vlesin: where func() is a stored function. so what should be written to slow query log in that case?

(2012-05-15 11:12:32) vlesin: KAlexey: In current implementation in the case when log_slow_sp_statements is off we will see the whole query in slow log. When log_slow_sp_statements is off only statements of func(a) will be in slow log.

(2012-05-15 11:17:31) KAlexey: vlesin: the thing is, if log_slow_sp_statements is on, and the stored function itself is fast, but the query itself is slow (i.e. we have many rows in t1), we won't see anything in the slow log...

(2012-05-15 11:18:26) KAlexey: another interesting case is nested stored routines

(2012-05-15 11:18:52) KAlexey: the log-slow-sp-statements BP says "ignore CALL statements, only log individual statements"

(2012-05-15 11:19:16) KAlexey: but whaat if a CALL statement is also an individual statement in another stored routine?

(2012-05-15 11:19:19) vlesin: KAlexey: I think we should extend the current blueprint.

(2012-05-15 11:19:34) KAlexey: sure, the question is how :)

(2012-05-15 11:34:12) vlesin: KAlexey: "if a CALL statement is also an individual statement in another stored routine" - I don't see any trouble here. We log SP name with each statement. If there are some slow queries inside of SP "A" which is inside if SP "B" then that statements will be logged with "A" name. And I think it's enough for problem diagnostics.

(2012-05-15 11:44:23) vlesin: About functions. I think we should log a query with function call if that query is slow itself. But if log_slow_sp_statements is on we should log the execution time of query itself(without functions execution time), and if log_slow_sp_statements is off the execution time of all function calls should be taken into account. How do you think?

(2012-05-15 11:45:56) KAlexey: vlesin: you can ask for feedback in experts@

(2012-05-15 11:46:40) KAlexey: vlesin: i.e. just describe the edge cases with nested stored routines and slow queries vs. slow stored functions and ask what people would like to see in the slow log in those cases

(2012-05-15 11:47:03) vlesin: KAlexey: ok

(?)

Work Items

This blueprint contains Public information 
Everyone can see this information.