Improve slow-log reporting for queries in stored procs
If log_slow_
- 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_
- 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:
- 5.5.41-37.0
- Started by
- Laurynas Biveinis
- Completed by
- Laurynas Biveinis
Related branches
Related bugs
Sprints
Whiteboard
Following is done:
When log_slow_
- 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_
===============
(2012-05-15 10:47:59) KAlexey: vlesin: so how do you propose to solve this problem for query_response_
(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_
(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-
(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_
(2012-05-15 11:17:31) KAlexey: vlesin: the thing is, if log_slow_
(2012-05-15 11:18:26) KAlexey: another interesting case is nested stored routines
(2012-05-15 11:18:52) KAlexey: the log-slow-
(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_
(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