Tests for MDEV-18892 Regression in slow log and admin statements

The patch for MDEV-15945 fixed MDEV-18892. Adding tests only.
MariaDB · Mar 12, 2019 · 90ce95d · 90ce95d
1 parent 3b2a568
commit 90ce95d
Show file tree

Hide file tree

Showing 3 changed files with 266 additions and 0 deletions.
diff --git a/mysql-test/r/log_slow_debug.result b/mysql-test/r/log_slow_debug.result
@@ -0,0 +1,137 @@
+SET @org_slow_query_log= @@global.slow_query_log;
+SET @org_log_output= @@global.log_output;
+SET @org_log_slow_admin_statements= @@global.log_slow_admin_statements;
+SET @@GLOBAL.slow_query_log=OFF;
+SET @@GLOBAL.log_output='TABLE';
+FLUSH SLOW LOGS;
+SET @@GLOBAL.slow_query_log=ON;
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET SESSION debug_dbug="+d,simulate_slow_query";
+CREATE PROCEDURE show_slow_log()
+BEGIN
+SELECT CONCAT('[slow] ', sql_text) AS sql_text
+FROM mysql.slow_log
+WHERE sql_text NOT LIKE '%debug_dbug%';
+END
+$$
+#
+# Expect all admin statements in the slow log (ON,DEFAULT)
+#
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET log_slow_filter=DEFAULT;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+sql_text
+[slow] TRUNCATE TABLE mysql.slow_log
+[slow] CREATE TABLE t1 (a INT)
+[slow] CREATE INDEX t1a ON t1 (a)
+[slow] DROP INDEX t1a ON t1
+[slow] DROP TABLE t1
+[slow] CREATE TABLE t2 (a INT)
+[slow] ALTER TABLE t2 RENAME t2
+[slow] RENAME TABLE t2 TO t3
+[slow] DROP TABLE t3
+[slow] CREATE TABLE t4 (a INT)
+[slow] PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1'
+[slow] ALTER TABLE t4 MODIFY a INT DEFAULT 1
+[slow] DEALLOCATE PREPARE stmt
+[slow] DROP TABLE t4
+#
+# Expect all admin statements in the slow log (ON,admin)
+#
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET log_slow_filter=admin;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+sql_text
+[slow] CREATE INDEX t1a ON t1 (a)
+[slow] DROP INDEX t1a ON t1
+[slow] ALTER TABLE t2 RENAME t2
+[slow] ALTER TABLE t4 MODIFY a INT DEFAULT 1
+#
+# Expect none of admin DDL statements in the slow log (ON,filesort)
+#
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET log_slow_filter=filesort;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+sql_text
+#
+# Expect none of admin statements in the slow log (OFF,DEFAULT)
+#
+SET @@GLOBAL.log_slow_admin_statements=OFF;
+SET log_slow_filter=DEFAULT;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+sql_text
+[slow] TRUNCATE TABLE mysql.slow_log
+[slow] CREATE TABLE t1 (a INT)
+[slow] DROP TABLE t1
+[slow] CREATE TABLE t2 (a INT)
+[slow] RENAME TABLE t2 TO t3
+[slow] DROP TABLE t3
+[slow] CREATE TABLE t4 (a INT)
+[slow] PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1'
+[slow] DEALLOCATE PREPARE stmt
+[slow] DROP TABLE t4
+#
+# Clean up
+#
+SET SESSION debug_dbug="-d,simulate_slow_query";
+TRUNCATE mysql.slow_log;
+SET @@global.slow_query_log= @org_slow_query_log;
+SET @@global.log_output= @org_log_output;
+SET @@global.log_slow_admin_statements= @org_log_slow_admin_statements;
+DROP PROCEDURE show_slow_log;
diff --git a/mysql-test/t/log_slow_debug.test b/mysql-test/t/log_slow_debug.test
@@ -0,0 +1,126 @@
+-- source include/have_debug.inc
+
+SET @org_slow_query_log= @@global.slow_query_log;
+SET @org_log_output= @@global.log_output;
+SET @org_log_slow_admin_statements= @@global.log_slow_admin_statements;
+
+SET @@GLOBAL.slow_query_log=OFF;
+SET @@GLOBAL.log_output='TABLE';
+FLUSH SLOW LOGS;
+SET @@GLOBAL.slow_query_log=ON;
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET SESSION debug_dbug="+d,simulate_slow_query";
+
+DELIMITER $$;
+CREATE PROCEDURE show_slow_log()
+BEGIN
+  SELECT CONCAT('[slow] ', sql_text) AS sql_text
+    FROM mysql.slow_log
+     WHERE sql_text NOT LIKE '%debug_dbug%';
+END
+$$
+DELIMITER ;$$
+
+
+--echo #
+--echo # Expect all admin statements in the slow log (ON,DEFAULT)
+--echo #
+
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET log_slow_filter=DEFAULT;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+
+
+--echo #
+--echo # Expect all admin statements in the slow log (ON,admin)
+--echo #
+
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET log_slow_filter=admin;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+
+
+--echo #
+--echo # Expect none of admin DDL statements in the slow log (ON,filesort)
+--echo #
+
+SET @@GLOBAL.log_slow_admin_statements=ON;
+SET log_slow_filter=filesort;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+
+
+--echo #
+--echo # Expect none of admin statements in the slow log (OFF,DEFAULT)
+--echo #
+
+SET @@GLOBAL.log_slow_admin_statements=OFF;
+SET log_slow_filter=DEFAULT;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE INDEX t1a ON t1 (a);
+DROP INDEX t1a ON t1;
+DROP TABLE t1;
+CREATE TABLE t2 (a INT);
+ALTER TABLE t2 RENAME t2;
+RENAME TABLE t2 TO t3;
+DROP TABLE t3;
+CREATE TABLE t4 (a INT);
+PREPARE stmt FROM 'ALTER TABLE t4 MODIFY a INT DEFAULT 1';
+EXECUTE stmt;
+DEALLOCATE PREPARE stmt;
+DROP TABLE t4;
+CALL show_slow_log();
+
+
+--echo #
+--echo # Clean up
+--echo #
+
+SET SESSION debug_dbug="-d,simulate_slow_query";
+TRUNCATE mysql.slow_log;
+SET @@global.slow_query_log= @org_slow_query_log;
+SET @@global.log_output= @org_log_output;
+SET @@global.log_slow_admin_statements= @org_log_slow_admin_statements;
+DROP PROCEDURE show_slow_log;
diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc
@@ -2047,6 +2047,9 @@ void log_slow_statement(THD *thd)
   if (!thd->enable_slow_log)
     goto end; // E.g. SP statement
 
+  DBUG_EXECUTE_IF("simulate_slow_query",
+                  thd->server_status|= SERVER_QUERY_WAS_SLOW;);
+
   if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
        ((thd->server_status &
          (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&