Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-18892

Regression in slow log and admin statements

Details

    Description

      There is a regression caused by MDEV-18333.

      As of this commit before MDEV-18333:

      commit f2e1451740d417f1c9ea8626d937fbcacc91bb55
      Merge: e39d6e0 2d34713
      Author: Oleksandr Byelkin <sanja@mariadb.com>
      Date:   Fri Mar 1 15:52:06 2019 +0100
      

      The following script

      FLUSH SLOW LOGS;
      SET @@GLOBAL.slow_query_log=ON;
      SET @@GLOBAL.log_output='TABLE';
      SET @@SESSION.slow_query_log=ON;
      SET @@SESSION.long_query_time=0.000001;
       
      SET @@GLOBAL.log_slow_admin_statements=OFF;
      SET log_slow_filter=DEFAULT;
      TRUNCATE TABLE mysql.slow_log;
      CREATE TABLE t1 (a INT);
      INSERT INTO t1 VALUES (1),(2),(3),(4);
      ALTER TABLE t1 ADD b INT;
      PREPARE stmt FROM 'ALTER TABLE t1 ADD c INT';
      EXECUTE stmt;
      DEALLOCATE PREPARE stmt;
      DROP TABLE t1;
      SELECT db, user_host, sql_text FROM mysql.slow_log WHERE sql_text NOT LIKE '%debug_dbug%';
      

      produced this output:

      +------+---------------------------+----------------------------------------------+
      | db   | user_host                 | sql_text                                     |
      +------+---------------------------+----------------------------------------------+
      | test | root[root] @ localhost [] | TRUNCATE TABLE mysql.slow_log                |
      | test | root[root] @ localhost [] | CREATE TABLE t1 (a INT)                      |
      | test | root[root] @ localhost [] | INSERT INTO t1 VALUES (1),(2),(3),(4)        |
      | test | root[root] @ localhost [] | PREPARE stmt FROM 'ALTER TABLE t1 ADD c INT' |
      | test | root[root] @ localhost [] | DEALLOCATE PREPARE stmt                      |
      | test | root[root] @ localhost [] | DROP TABLE t1                                |
      +------+---------------------------+----------------------------------------------+
      

      As of this later commit (which includes MDEV-18333):

      commit ea52ecbc103b1424cf0b6f8faf990676b2b57a63
      Merge: 2a2ab12 149b754
      Author: Sergey Vojtovich <svoj@mariadb.org>
      Date:   Mon Mar 11 22:50:24 2019 +0400
      

      the same script returns a different output:

      +------+---------------------------+----------------------------------------------+
      | db   | user_host                 | sql_text                                     |
      +------+---------------------------+----------------------------------------------+
      | test | root[root] @ localhost [] | TRUNCATE TABLE mysql.slow_log                |
      | test | root[root] @ localhost [] | CREATE TABLE t1 (a INT)                      |
      | test | root[root] @ localhost [] | INSERT INTO t1 VALUES (1),(2),(3),(4)        |
      | test | root[root] @ localhost [] | PREPARE stmt FROM 'ALTER TABLE t1 ADD c INT' |
      | test | root[root] @ localhost [] | ALTER TABLE t1 ADD c INT                     |
      | test | root[root] @ localhost [] | DEALLOCATE PREPARE stmt                      |
      | test | root[root] @ localhost [] | DROP TABLE t1                                |
      +------+---------------------------+----------------------------------------------+
      

      Notice, before MDEV-18333, non of the ALTER statements appeared in the slow log.

      With MDEV-18333:

      • the directly executed ALTER is not in the slow log (correct)
      • the prepared ALTER is in the log (wrong)

      The served does not respect the log_slow_admin_statements setting with prepared statements any more.

      Attachments

        Issue Links

          Activity

            There is also a problem with CREATE INDEX and DROP INDEX statements.
            As of this commit before MDEV-18333:

            commit f2e1451740d417f1c9ea8626d937fbcacc91bb55
            Merge: e39d6e0 2d34713
            Author: Oleksandr Byelkin <sanja@mariadb.com>
            Date:   Fri Mar 1 15:52:06 2019 +0100
            

            The following script

            FLUSH SLOW LOGS;
            SET @@GLOBAL.slow_query_log=ON;
            SET @@GLOBAL.log_output='TABLE';
            SET @@SESSION.slow_query_log=ON;
            SET @@SESSION.long_query_time=0.000001;
             
            SET @@GLOBAL.log_slow_admin_statements=OFF;
            SET log_slow_filter=DEFAULT;
            TRUNCATE TABLE mysql.slow_log;
            CREATE TABLE t1 (a INT);
            INSERT INTO t1 VALUES (1),(2),(3),(4);
            CREATE INDEX idx ON t1 (a);
            DROP TABLE t1;
            SELECT db, user_host, sql_text FROM mysql.slow_log WHERE sql_text NOT LIKE '%debug_dbug%';
            

            produced this output:

            +------+---------------------------+---------------------------------------+
            | db   | user_host                 | sql_text                              |
            +------+---------------------------+---------------------------------------+
            | test | root[root] @ localhost [] | TRUNCATE TABLE mysql.slow_log         |
            | test | root[root] @ localhost [] | CREATE TABLE t1 (a INT)               |
            | test | root[root] @ localhost [] | INSERT INTO t1 VALUES (1),(2),(3),(4) |
            | test | root[root] @ localhost [] | DROP TABLE t1                         |
            +------+---------------------------+---------------------------------------+
            

            As of this later commit (which includes MDEV-18333):

            commit ea52ecbc103b1424cf0b6f8faf990676b2b57a63
            Merge: 2a2ab12 149b754
            Author: Sergey Vojtovich <svoj@mariadb.org>
            Date:   Mon Mar 11 22:50:24 2019 +0400
            

            the same script returns a different output:

            +------+---------------------------+---------------------------------------+
            | db   | user_host                 | sql_text                              |
            +------+---------------------------+---------------------------------------+
            | test | root[root] @ localhost [] | TRUNCATE TABLE mysql.slow_log         |
            | test | root[root] @ localhost [] | CREATE TABLE t1 (a INT)               |
            | test | root[root] @ localhost [] | INSERT INTO t1 VALUES (1),(2),(3),(4) |
            | test | root[root] @ localhost [] | CREATE INDEX idx ON t1 (a)            |
            | test | root[root] @ localhost [] | DROP TABLE t1                         |
            +------+---------------------------+---------------------------------------+
            

            Notice, before MDEV-18333, the CREATE INDEX statement did not appeare in the slow log,
            with MDEV-18333 it does.

            bar Alexander Barkov added a comment - There is also a problem with CREATE INDEX and DROP INDEX statements. As of this commit before MDEV-18333 : commit f2e1451740d417f1c9ea8626d937fbcacc91bb55 Merge: e39d6e0 2d34713 Author: Oleksandr Byelkin <sanja@mariadb.com> Date: Fri Mar 1 15:52:06 2019 +0100 The following script FLUSH SLOW LOGS; SET @@ GLOBAL .slow_query_log= ON ; SET @@ GLOBAL .log_output= 'TABLE' ; SET @@SESSION.slow_query_log= ON ; SET @@SESSION.long_query_time=0.000001;   SET @@ GLOBAL .log_slow_admin_statements= OFF ; SET log_slow_filter= DEFAULT ; TRUNCATE TABLE mysql.slow_log; CREATE TABLE t1 (a INT ); INSERT INTO t1 VALUES (1),(2),(3),(4); CREATE INDEX idx ON t1 (a); DROP TABLE t1; SELECT db, user_host, sql_text FROM mysql.slow_log WHERE sql_text NOT LIKE '%debug_dbug%' ; produced this output: +------+---------------------------+---------------------------------------+ | db | user_host | sql_text | +------+---------------------------+---------------------------------------+ | test | root[root] @ localhost [] | TRUNCATE TABLE mysql.slow_log | | test | root[root] @ localhost [] | CREATE TABLE t1 (a INT) | | test | root[root] @ localhost [] | INSERT INTO t1 VALUES (1),(2),(3),(4) | | test | root[root] @ localhost [] | DROP TABLE t1 | +------+---------------------------+---------------------------------------+ As of this later commit (which includes MDEV-18333 ): commit ea52ecbc103b1424cf0b6f8faf990676b2b57a63 Merge: 2a2ab12 149b754 Author: Sergey Vojtovich <svoj@mariadb.org> Date: Mon Mar 11 22:50:24 2019 +0400 the same script returns a different output: +------+---------------------------+---------------------------------------+ | db | user_host | sql_text | +------+---------------------------+---------------------------------------+ | test | root[root] @ localhost [] | TRUNCATE TABLE mysql.slow_log | | test | root[root] @ localhost [] | CREATE TABLE t1 (a INT) | | test | root[root] @ localhost [] | INSERT INTO t1 VALUES (1),(2),(3),(4) | | test | root[root] @ localhost [] | CREATE INDEX idx ON t1 (a) | | test | root[root] @ localhost [] | DROP TABLE t1 | +------+---------------------------+---------------------------------------+ Notice, before MDEV-18333 , the CREATE INDEX statement did not appeare in the slow log, with MDEV-18333 it does.

            People

              bar Alexander Barkov
              bar Alexander Barkov
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.