[MDEV-18892] Regression in slow log and admin statements Created: 2019-03-12  Updated: 2019-03-25  Resolved: 2019-03-13

Status: Closed
Project: MariaDB Server
Component/s: Prepared Statements
Affects Version/s: 10.1
Fix Version/s: 10.1.39

Type: Bug Priority: Major
Reporter: Alexander Barkov Assignee: Alexander Barkov
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-18333 Slow_queries count doesn't increase w... Closed

 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.



 Comments   
Comment by Alexander Barkov [ 2019-03-12 ]

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.

Generated at Thu Feb 08 08:47:31 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.