MySQL Bugs: #76585: Runtime changes to `long_query

Bug #76585	Runtime changes to `long_query_time` are ignored.
Submitted:	3 Apr 2015 10:07	Modified:	19 Feb 2018 14:36
Reporter:	Saverio Miroddi	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	5.6.27, 5.7.21	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
I've set the MySQL server to log the slow queries, with the following parameters (SHOW GLOBAL VARIABLES LIKE '...'):

+-------------------------------+----------+
| Variable_name                 | Value    |
+-------------------------------+----------+
| log_slow_admin_statements     | OFF      |
| long_query_time               | 5.000000 |
| log_queries_not_using_indexes | OFF      |
+-------------------------------+----------+

According to the documentation at https://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html, such options should cause the logging of queries slower than 5 seconds, excluding the admin statements, and ignoring the fact that an index is used or not.

In spite of this, even very fast (sub-millisecond) queries are logged, when I set 'slow_query_log' to 1.

The documentation in the page referenced above doesn't mention anything about the server restart/reload, so I'm puzzled by this behavior, so I assume that live changes to the global variables should have effect.

Is this a bug, or is a reload/restart needed, in which case it's not mentioned in the documentation?

How to repeat:
Not sure what's causing this, but the my.cnf contains:

slow_query_log                         = 0
long_query_time                        = 0
log_slow_admin_statements              = 1
log_queries_not_using_indexes          = 1
log_throttle_queries_not_using_indexes = 0

Same things on 5.6.24 - live changes to long_query_time don't have any effect; the effective value is always the one in the configuration file.

I've done a few other tests.

A random combination of stopping/starting the slow log and changing the slow log file worked, but simple changes generally don't yield the expected effect.

This is still an issue on 5.6.27:

Client commands:

    mysql> SET GLOBAL long_query_time = 5; SET GLOBAL slow_query_log=0; SET GLOBAL slow_query_log=1;
    Query OK, 0 rows affected (0.00 sec)
    
    Query OK, 0 rows affected (0.00 sec)
    
    Query OK, 0 rows affected (0.00 sec)
    
    mysql> SELECT SLEEP(4);
    +----------+
    | SLEEP(4) |
    +----------+
    |        0 |
    +----------+
    1 row in set (4.00 sec)
    
    mysql> SELECT SLEEP(6);
    +----------+
    | SLEEP(6) |
    +----------+
    |        0 |
    +----------+
    1 row in set (6.00 sec)
    
    mysql> SET GLOBAL long_query_time = 3; SET GLOBAL slow_query_log=0; SET GLOBAL slow_query_log=1;
    Query OK, 0 rows affected (0.00 sec)
    
    Query OK, 0 rows affected (0.00 sec)
    
    Query OK, 0 rows affected (0.00 sec)
    
    mysql> SELECT SLEEP(4);
    +----------+
    | SLEEP(4) |
    +----------+
    |        0 |
    +----------+
    1 row in set (4.00 sec)
    
    mysql> SELECT SLEEP(6);
    +----------+
    | SLEEP(6) |
    +----------+
    |        0 |
    +----------+
    1 row in set (6.00 sec)

Log file content (edited):

    [file reopened]
    Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
    Time                 Id Command    Argument
    # Time: 160503 16:39:51
    # User@Host: my_user[my_user] @ localhost []  Id: 100165
    # Schema: my_db  Last_errno: 0  Killed: 0
    # Query_time: 6.000184  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
    # Bytes_sent: 63
    use my_db;
    SET timestamp=1462289991;
    SELECT SLEEP(6);
    [file reopened]
    Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
    Time                 Id Command    Argument
    # Time: 160503 16:40:27
    # User@Host: my_user[my_user] @ localhost []  Id: 100165
    # Schema: my_db  Last_errno: 0  Killed: 0
    # Query_time: 6.000191  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
    # Bytes_sent: 63
    use my_db;
    SET timestamp=1462290027;
    SELECT SLEEP(6);

Made the submission more accurate. More specifically:

MySQL sticks to the `long_query_time` quantity specified in the configuration time. Any runtime change is set (as variable value) but ignored.

Thank you for the bug report. We don't have here a test case to try, please try latest 5.7.21 version.

Hello, I've retried the provided statements again, and confirm that this is not an issue; in order to affect the current session, the session-level variable needs to be changed, not the global.

I'm closing the bug.