log_slow_sp_statements interferes with log_slow_admin_statements

[Alexey Kopytov]

When a stored routine calls an "administrative" command such as OPTIMIZE TABLE, ANALYZE TABLE, ALTER TABLE, CREATE/DROP INDEX, etc. the effective value of log_slow_sp_statements is overwritten by the value of log_slow_admin_statements.

More specifically, mysql_execute_command() assigns the value of opt_log_slow_admin_statements to thd->enable_slow_log before execution of an administrative command. The original value of thd->enable_slow_log is not restored back until the next statement execution. This becomes a problem for "substatements" of a stored routine, since the code relies on thd->enable_slow_log to decide if log_slow_statement() should be called for individual statements in a stored routine.

As a result, with log_slow_sp_statements ON and log_slow_admin_statements OFF, the first administrative command in a stored routine will disable slow logging for all subsequent statements in that routine.

Conversely, with log_slow_sp_statements OFF and log_slow_admin_statements ON, the first administrative statement in a stored routine will enable slow logging for all subsequent statements in that routine.

Steps to reproduce:

1. ./mysqld --log-slow-admin-statements=0
2. create the following table and SP:

CREATE TABLE t1(a int);
delimiter //
CREATE PROCEDURE test() BEGIN INSERT INTO t1 VALUES(0); CREATE INDEX i ON t1(a); INSERT INTO t1 VALUES(1); END//
delimiter ;

3. in a debugger, set a breakpoint on log_slow_statement()

4. execute "call test();"

5. log_slow_statement() will only be called for INSERT before CREATE INDEX, but not for the one after it.

[Laurynas Biveinis (laurynas-biveinis)]

https://github.com/percona/percona-server/pull/597, https://github.com/percona/percona-server/pull/1099, https://github.com/percona/percona-server/pull/1100

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1189