[MDEV-18892] Regression in slow log and admin statements - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1(EOL)
Fix Version/s: 10.1.39
Component/s: Prepared Statements
Labels:
None

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

relates to

MDEV-18333 Slow_queries count doesn't increase when slow_query_log is turned off

Closed

Activity

Ascending order - Click to sort in descending order

Alexander Barkov created issue - 2019-03-12 05:17

Alexander Barkov made changes - 2019-03-12 05:17

Field	Original Value	New Value
Link		This issue relates to ~~MDEV-18333~~ [ ~~MDEV-18333~~ ]

Alexander Barkov made changes - 2019-03-12 05:18

Description

There is a regression caused by ~~MDEV-18333~~.

As of this commit before ~~MDEV-18333~~:

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

The following script

{code:sql}
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%';
{code}

produced this output:

{noformat}
+------+---------------------------+----------------------------------------------+
| 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 |
+------+---------------------------+----------------------------------------------+
{noformat}

As of this later commit (which includes ~~MDEV-18333~~):
{noformat}
commit ea52ecbc103b1424cf0b6f8faf990676b2b57a63
Merge: 2a2ab12 149b754
Author: Sergey Vojtovich <svoj@mariadb.org>
Date: Mon Mar 11 22:50:24 2019 +0400
{noformat}

the same script returns a different output:

{noformat}
+------+---------------------------+----------------------------------------------+
| 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 |
+------+---------------------------+----------------------------------------------+
{noformat}

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
- the prepared {{ALTER}} is in the log

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

There is a regression caused by ~~MDEV-18333~~.

As of this commit before ~~MDEV-18333~~:

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

The following script

{code:sql}
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%';
{code}

produced this output:

{noformat}
+------+---------------------------+----------------------------------------------+
| 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 |
+------+---------------------------+----------------------------------------------+
{noformat}

As of this later commit (which includes ~~MDEV-18333~~):
{noformat}
commit ea52ecbc103b1424cf0b6f8faf990676b2b57a63
Merge: 2a2ab12 149b754
Author: Sergey Vojtovich <svoj@mariadb.org>
Date: Mon Mar 11 22:50:24 2019 +0400
{noformat}

the same script returns a different output:

{noformat}
+------+---------------------------+----------------------------------------------+
| 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 |
+------+---------------------------+----------------------------------------------+
{noformat}

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.

Alexander Barkov added a comment - 2019-03-12 05:25

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.

Alexander Barkov added a comment - 2019-03-12 05:25 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.

Alexander Barkov made changes - 2019-03-13 05:37

issue.field.resolutiondate

2019-03-13 05:37:43.0

2019-03-13 05:37:43.943

Alexander Barkov made changes - 2019-03-13 05:37

Fix Version/s		10.1.39 [ 23305 ]
Fix Version/s	10.1 [ 16100 ]
Resolution		Fixed [ 1 ]
Status	Open [ 1 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:49

Workflow

MariaDB v3 [ 93122 ]

MariaDB v4 [ 155903 ]

People

Assignee:: Alexander Barkov

Reporter:: Alexander Barkov

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2019-03-12 05:17

Updated:: 2019-03-25 03:47

Resolved:: 2019-03-13 05:37

Git Integration

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

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration