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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.3.7, 10.4.2, 10.1.37, 10.2.21
Fix Version/s: 10.2.23, 10.1.39, 10.3.14, 10.4.4
Component/s: Configuration
Labels:
None

Description

As per the manual,

Slow_queries
Description: Number of queries which took longer than long_query_time to run. The slow query log does not need to be active for this to be recorded.
https://mariadb.com/kb/en/library/server-status-variables/#slow_queries

But in real scenario, we have to active slow query log otherwise, it will not be recoded.

MariaDB [test]> select @@long_query_time, @@slow_query_log;

+-------------------+------------------+

| @@long_query_time | @@slow_query_log |

+-------------------+------------------+

|         10.000000 |                0 |

+-------------------+------------------+

1 row in set (0.029 sec)

MariaDB [test]> show global status like 'slow_queries';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| Slow_queries  | 0     |

+---------------+-------+

1 row in set (0.005 sec)

MariaDB [test]> set global long_query_time=0.1;

Query OK, 0 rows affected (0.027 sec)

MariaDB [test]> \r

Connection id:    10

Current database: test

MariaDB [test]> select sleep(1) from mysql.user limit 2;

+----------+

| sleep(1) |

+----------+

|        0 |

|        0 |

+----------+

2 rows in set (2.079 sec)

MariaDB [test]> show global status like 'slow_queries';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| Slow_queries  | 0     |

+---------------+-------+

1 row in set (0.005 sec)

MariaDB [test]> set global slow_query_log=ON;

Query OK, 0 rows affected (0.038 sec)

MariaDB [test]> \r

Connection id:    11

Current database: test

MariaDB [test]> select @@long_query_time, @@slow_query_log;

+-------------------+------------------+

| @@long_query_time | @@slow_query_log |

+-------------------+------------------+

|          0.100000 |                1 |

+-------------------+------------------+

1 row in set (0.001 sec)

MariaDB [test]> select sleep(1) from mysql.user limit 2;

+----------+

| sleep(1) |

+----------+

|        0 |

|        0 |

+----------+

2 rows in set (1.996 sec)

MariaDB [test]> show global status like 'slow_queries';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| Slow_queries  | 1     |

+---------------+-------+

1 row in set (0.005 sec)

Attachments

Issue Links

relates to

MDEV-18892 Regression in slow log and admin statements

Closed

MDEV-18907 Slow log: RENAME TABLE is not "admin", while ALTER TABLE..RENAME is

Closed

Activity

Ascending order - Click to sort in descending order

Nilnandan Joshi created issue - 2019-01-22 06:27

Nilnandan Joshi made changes - 2019-01-22 06:31

Field	Original Value	New Value
Affects Version/s		10.1.37 [ 23204 ]

Elena Stepanova made changes - 2019-01-22 21:41

Status

Open [ 1 ]

Confirmed [ 10101 ]

Elena Stepanova added a comment - 2019-01-22 21:44

The difference was introduced by this commit:

commit e2b2bde358f434d945e9730acfbc6eedeb9ab8a2

Author: Monty

Date:   Sun Aug 3 15:26:47 2014 +0300

    Made sql_log_slow a session variable

    mysqldump:

    - Added --log-queries to allow one to disable logging for the dump

    sql/log_event.cc:

    - Removed setting of enable_slow_log as it's not required anymore.

    sql/sql_parse.cc:

    - Set enable_slow_log to value of thd->variables.sql_log_slow as this will speed up tests if slow log is disabled.

    - opt_log_slow_admin_statements can now only disable slow log, not enable it.

    sql/sql_explain.cc:

    - Minor cleanup

    Other things:

    - Added sql_log_slow to system variables.

    - Changed opt_slow_log to global_system_variables.sql_log_slow in all files

    - Updated tests to reflect changes

If we want to keep it this way, documentation needs to be updated.

Elena Stepanova added a comment - 2019-01-22 21:44 The difference was introduced by this commit: commit e2b2bde358f434d945e9730acfbc6eedeb9ab8a2 Author: Monty Date: Sun Aug 3 15:26:47 2014 +0300 Made sql_log_slow a session variable mysqldump: - Added --log-queries to allow one to disable logging for the dump sql/log_event.cc: - Removed setting of enable_slow_log as it's not required anymore. sql/sql_parse.cc: - Set enable_slow_log to value of thd->variables.sql_log_slow as this will speed up tests if slow log is disabled. - opt_log_slow_admin_statements can now only disable slow log, not enable it. sql/sql_explain.cc: - Minor cleanup Other things: - Added sql_log_slow to system variables. - Changed opt_slow_log to global_system_variables.sql_log_slow in all files - Updated tests to reflect changes If we want to keep it this way, documentation needs to be updated.

Elena Stepanova made changes - 2019-01-22 21:44

Component/s		Configuration [ 13904 ]
Fix Version/s		10.1 [ 16100 ]
Fix Version/s		10.2 [ 14601 ]
Fix Version/s		10.3 [ 22126 ]
Assignee		Sergei Golubchik [ serg ]

Sergei Golubchik made changes - 2019-01-28 15:22

Assignee

Sergei Golubchik [ serg ]

Sergey Vojtovich [ svoj ]

Sergei Golubchik made changes - 2019-01-31 18:34

Assignee

Sergey Vojtovich [ svoj ]

Alexander Barkov [ bar ]

Sergei Golubchik made changes - 2019-02-12 19:39

Priority

Major [ 3 ]

Critical [ 2 ]

Alexander Barkov added a comment - 2019-02-13 07:44

A smaller script demonstrating the same problem:

SET GLOBAL slow_query_log=OFF;

SET long_query_time=0.1;

SELECT VARIABLE_VALUE INTO @global_slow_queries

  FROM INFORMATION_SCHEMA.GLOBAL_STATUS

  WHERE VARIABLE_NAME='SLOW_QUERIES';

SELECT sleep(0.2) FROM DUAL;

SELECT

    CAST(VARIABLE_VALUE AS UNSIGNED)-@global_slow_queries AS Slow_queries_increment

  FROM

    INFORMATION_SCHEMA.GLOBAL_STATUS

  WHERE

    VARIABLE_NAME='SLOW_QUERIES';

+------------------------+

| Slow_queries_increment |

+------------------------+

|                      0 |

+------------------------+

The expected Slow_queries_increment is 0.

Alexander Barkov added a comment - 2019-02-13 07:44 A smaller script demonstrating the same problem: SET GLOBAL slow_query_log= OFF ; SET long_query_time=0.1; SELECT VARIABLE_VALUE INTO @global_slow_queries FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME= 'SLOW_QUERIES' ; SELECT sleep(0.2) FROM DUAL; SELECT CAST (VARIABLE_VALUE AS UNSIGNED)-@global_slow_queries AS Slow_queries_increment FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME= 'SLOW_QUERIES' ; +------------------------+ | Slow_queries_increment | +------------------------+ | 0 | +------------------------+ The expected Slow_queries_increment is 0 .

Alexander Barkov made changes - 2019-02-13 09:40

Fix Version/s

10.4 [ 22408 ]

Alexander Barkov made changes - 2019-02-13 09:41

Affects Version/s

10.4.2 [ 23229 ]

Sergei Golubchik made changes - 2019-02-25 23:17

Priority

Critical [ 2 ]

Blocker [ 1 ]

Sergei Golubchik made changes - 2019-02-25 23:17

Fix Version/s

10.4 [ 22408 ]

Sergei Golubchik made changes - 2019-02-25 23:18

Priority

Blocker [ 1 ]

Critical [ 2 ]

Alexander Barkov added a comment - 2019-02-27 05:17 - edited

Discussed with Monty, agreed that it should work as follows:

Inside stored routines logging and Slow_queries increment are always disabled. Values of @@GLOBAL.slow_query_log and @@SESSION.slow_query_log are not important in this case.
Otherwise, when outside of stored routines:
- @@GLOBAL.slow_query_log and @@SESSION.slow_query_log set to FALSE disable only logging! They do not affect Slow_queries increment.
- If @@GLOBAL.slow_query_log is set to FALSE, it disables logging globally. The value of @@SESSION.slow_query_log does not matter in this case.
- If @@GLOBAL.slow_query_log is TRUE, the logging is allowed globally, but an individual thread can disable logging by setting @@SESSION.slow_query_log to FALSE. This is needed for mysqldump.

Alexander Barkov added a comment - 2019-02-27 05:17 - edited Discussed with Monty, agreed that it should work as follows: Inside stored routines logging and Slow_queries increment are always disabled. Values of @@GLOBAL.slow_query_log and @@SESSION.slow_query_log are not important in this case. Otherwise, when outside of stored routines: @@GLOBAL.slow_query_log and @@SESSION.slow_query_log set to FALSE disable only logging! They do not affect Slow_queries increment. If @@GLOBAL.slow_query_log is set to FALSE , it disables logging globally. The value of @@SESSION.slow_query_log does not matter in this case. If @@GLOBAL.slow_query_log is TRUE , the logging is allowed globally, but an individual thread can disable logging by setting @@SESSION.slow_query_log to FALSE . This is needed for mysqldump .

Alexander Barkov made changes - 2019-03-04 11:47

Fix Version/s		10.1.39 [ 23305 ]
Fix Version/s		10.2.23 [ 23307 ]
Fix Version/s		10.3.14 [ 23216 ]
Fix Version/s		10.4.4 [ 23310 ]
Fix Version/s	10.2 [ 14601 ]
Fix Version/s	10.1 [ 16100 ]
Fix Version/s	10.3 [ 22126 ]

Alexander Barkov made changes - 2019-03-04 11:48

issue.field.resolutiondate

2019-03-04 11:48:08.0

2019-03-04 11:48:08.188

Alexander Barkov made changes - 2019-03-04 11:48

Resolution		Fixed [ 1 ]
Status	Confirmed [ 10101 ]	Closed [ 6 ]

Marko Mäkelä added a comment - 2019-03-05 11:12

In 10.3, there are conflicts between this and ~~MDEV-7742~~/~~MDEV-8305~~ due to the removal of opt_log_slow_admin_statements in 10.3.1.
I was unable to resolve these conflicts, and I recorded a wrong result for main.log_slow in my merge.

bar, please fix 10.3 and close this ticket once done.

Marko Mäkelä added a comment - 2019-03-05 11:12 In 10.3, there are conflicts between this and MDEV-7742 / MDEV-8305 due to the removal of opt_log_slow_admin_statements in 10.3.1. I was unable to resolve these conflicts, and I recorded a wrong result for main.log_slow in my merge . bar , please fix 10.3 and close this ticket once done.

Marko Mäkelä made changes - 2019-03-05 11:12

Resolution	Fixed [ 1 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Alexander Barkov added a comment - 2019-03-06 13:10

Made a cleanup:

commit 26f0d72a3f9b92574b16fc0348f79f16ed8021d0
A cleanup for ~~MDEV-18333~~ Slow_queries count doesn't increase when slow_query_log is turned off

thd->lex->m_sql_cmd was not cleared between queries.
log_slow_query() could crash (when running mtr --ps) because of this.

Alexander Barkov added a comment - 2019-03-06 13:10 Made a cleanup: commit 26f0d72a3f9b92574b16fc0348f79f16ed8021d0 A cleanup for MDEV-18333 Slow_queries count doesn't increase when slow_query_log is turned off thd->lex->m_sql_cmd was not cleared between queries. log_slow_query() could crash (when running mtr --ps) because of this.

Alexander Barkov made changes - 2019-03-06 13:10

issue.field.resolutiondate

2019-03-06 13:10:45.0

2019-03-06 13:10:45.225

Alexander Barkov made changes - 2019-03-06 13:10

Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Alexander Barkov added a comment - 2019-03-06 16:40 - edited

Still needs adjustments in 10.3. Reopening again.

Alexander Barkov added a comment - 2019-03-06 16:40 - edited Still needs adjustments in 10.3. Reopening again.

Alexander Barkov made changes - 2019-03-06 16:40

Resolution	Fixed [ 1 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Alexander Barkov added a comment - 2019-03-06 19:46

Added an after-merge fix for 10.3.

Alexander Barkov added a comment - 2019-03-06 19:46 Added an after-merge fix for 10.3.

Alexander Barkov made changes - 2019-03-06 19:46

issue.field.resolutiondate

2019-03-06 19:46:30.0

2019-03-06 19:46:30.894

Alexander Barkov made changes - 2019-03-06 19:46

Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

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

Link

This issue relates to ~~MDEV-18892~~ [ ~~MDEV-18892~~ ]

Alexander Barkov made changes - 2019-03-13 09:57

Link

This issue relates to ~~MDEV-18907~~ [ ~~MDEV-18907~~ ]

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

Workflow

MariaDB v3 [ 91964 ]

MariaDB v4 [ 155566 ]

Jira Automation (IT) made changes - 2024-07-04 04:16

Zendesk Related Tickets

113021

People

Assignee:: Alexander Barkov

Reporter:: Nilnandan Joshi

Votes:: 1 Vote for this issue

Watchers:: 8 Start watching this issue

Dates

Created:: 2019-01-22 06:27

Updated:: 2024-07-07 23:21

Resolved:: 2019-03-06 19:46

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