There are quite a few more details listed there which may help shed light on the implementation, such as:
Prior to 5.5.41-37.0 implementation of logging stored procedures was logging the stored procedure CALLs themselves along with the queries inside the procedures. This meant that some queries were counted more than once which could make tracking the bad-performing queries harder and it would cause noise in the slow query log. Percona Server 5.5.41-37.0 implemented improvements for logging of stored procedures to the slow query log:
Each query from a stored procedure is now logged to the slow query log individually
CALL itself isn’t logged to the slow query log anymore as this would be counting twice for the same query which would lead to incorrect results
Queries that were called inside of stored procedures are annotated in the slow query log with the stored procedure name in which they run.
MDEV-7011 statement timeouts. currently max_statement_time limit applies to CALL statement as a whole, not to individual statements in the stored procedure. That was done, precisely, because CALL is logged in the slow query log as a whole, that is, the logic is — we measure time for the CALL, not for statements inside it. If slow query log will contain statements from inside the stored procedure, we might want to change max_statement_time to match this behavior.
MDEV-7444 currently audit plugin doesn't see statements inside the stored procedure, we might want to change this too
slow log can record EXPLAIN output for statements. it needs to work for statements inside a procedure too
Sergei Golubchik
added a comment - Few considerations:
MDEV-7011 statement timeouts. currently max_statement_time limit applies to CALL statement as a whole, not to individual statements in the stored procedure. That was done, precisely, because CALL is logged in the slow query log as a whole, that is, the logic is — we measure time for the CALL, not for statements inside it. If slow query log will contain statements from inside the stored procedure, we might want to change max_statement_time to match this behavior.
MDEV-7444 currently audit plugin doesn't see statements inside the stored procedure, we might want to change this too
slow log can record EXPLAIN output for statements. it needs to work for statements inside a procedure too
Colin Charles
added a comment - this is in Percona Server 5.5, 5.6 and 5.7 - we need to see this in MariaDB Server 10.2 please ( https://www.percona.com/doc/percona-server/5.7/diagnostics/slow_extended.html )
This functionality is now pushed to bb-10.3-monty to be included in next 10.3 alpha.
The differences to the patch in Percona server are:
Instead of adding a new variable for just logging to sp, I added two more general variables:
log_slow_disable_statements and log_disable_statements, which allowed me to make the following variables
obsolete: log_slow_slave_statements, log_slow_admin_statements. This allow the user to specify more exactly
what should not be logged. 'admin', 'call', 'slave' and 'sp'.
All the above variables are now session variables instead of global variables.
Status in slow log now show correct information for SP statements. CALL's correctly accumulates information from all included statements (This was not the case with the Percona patch).
From the commit statement (I have omitted internal changes not relevant for end user):
New functionallity:
Added new variables log_slow_disable_statements and log_disable_statements
that can be used to disable logging of certain queries to slow and
general log. Currently supported options are 'admin', 'call', 'slave'
and 'sp'.
Defaults are as before. Only 'sp' (stored procedure statements) is
disabled for slow and general_log.
Slow log to files now includes the following new information:
When logging stored procedure statements the name of stored
procedure is logged.
Number of created tmp_tables, tmp_disk_tables and the space used
by temporary tables.
When logging 'call', the logged status now contains the sum of all
included statements. Before only 'time' was correct.
Mapped some old variables to bitmaps (old variables can still be used)
Variable 'log_queries_not_using_indexes' is mapped to
log_slow_filter='not_using_index'
Variable 'log_slow_slave_statements' is mapped to
log_slow_disabled_statements='slave'
Variable 'log_slow_admin_statements' is mapped to
log_slow_disabled_statements='admin'
All the above variables are changed to session variables from global
variables
Michael Widenius
added a comment - This functionality is now pushed to bb-10.3-monty to be included in next 10.3 alpha.
The differences to the patch in Percona server are:
Instead of adding a new variable for just logging to sp, I added two more general variables:
log_slow_disable_statements and log_disable_statements, which allowed me to make the following variables
obsolete: log_slow_slave_statements, log_slow_admin_statements. This allow the user to specify more exactly
what should not be logged. 'admin', 'call', 'slave' and 'sp'.
All the above variables are now session variables instead of global variables.
Status in slow log now show correct information for SP statements. CALL's correctly accumulates information from all included statements (This was not the case with the Percona patch).
From the commit statement (I have omitted internal changes not relevant for end user):
New functionallity:
Added new variables log_slow_disable_statements and log_disable_statements
that can be used to disable logging of certain queries to slow and
general log. Currently supported options are 'admin', 'call', 'slave'
and 'sp'.
Defaults are as before. Only 'sp' (stored procedure statements) is
disabled for slow and general_log.
Slow log to files now includes the following new information:
When logging stored procedure statements the name of stored
procedure is logged.
Number of created tmp_tables, tmp_disk_tables and the space used
by temporary tables.
When logging 'call', the logged status now contains the sum of all
included statements. Before only 'time' was correct.
Mapped some old variables to bitmaps (old variables can still be used)
Variable 'log_queries_not_using_indexes' is mapped to
log_slow_filter='not_using_index'
Variable 'log_slow_slave_statements' is mapped to
log_slow_disabled_statements='slave'
Variable 'log_slow_admin_statements' is mapped to
log_slow_disabled_statements='admin'
All the above variables are changed to session variables from global
variables
Task
Major
Few considerations:
MDEV-7011statement timeouts. currently max_statement_time limit applies to CALL statement as a whole, not to individual statements in the stored procedure. That was done, precisely, because CALL is logged in the slow query log as a whole, that is, the logic is — we measure time for the CALL, not for statements inside it. If slow query log will contain statements from inside the stored procedure, we might want to change max_statement_time to match this behavior.MDEV-7444currently audit plugin doesn't see statements inside the stored procedure, we might want to change this too