[MDEV-18333] Slow_queries count doesn't increase when slow_query_log is turned off Created: 2019-01-22  Updated: 2020-08-25  Resolved: 2019-03-06

Status: Closed
Project: MariaDB Server
Component/s: Configuration
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

Type: Bug Priority: Critical
Reporter: Nilnandan Joshi Assignee: Alexander Barkov
Resolution: Fixed Votes: 1
Labels: None

Issue Links:
Relates
relates to MDEV-18892 Regression in slow log and admin stat... Closed
relates to MDEV-18907 Slow log: RENAME TABLE is not "admin"... Closed

 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)



 Comments   
Comment by Elena Stepanova [ 2019-01-22 ]

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.

Comment by Alexander Barkov [ 2019-02-13 ]

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.

Comment by Alexander Barkov [ 2019-02-27 ]

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.
Comment by Marko Mäkelä [ 2019-03-05 ]

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.

Comment by Alexander Barkov [ 2019-03-06 ]

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.

Comment by Alexander Barkov [ 2019-03-06 ]

Still needs adjustments in 10.3. Reopening again.

Comment by Alexander Barkov [ 2019-03-06 ]

Added an after-merge fix for 10.3.

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