Bug #28808 log_queries_not_using_indexes variable dynamic change is ignored
Submitted: 31 May 2007 14:00 Modified: 10 Jul 2007 22:14
Reporter: Valeriy Kravchuk Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.0.44-BK, 5.0.40, 5.0.34, 5.0.24a OS:Linux
Assigned to: Ramil Kalimullin CPU Architecture:Any
Tags: bfsm_2007_06_21, bfsm_2007_06_28

[31 May 2007 14:00] Valeriy Kravchuk
Description:
According to the manual (http://dev.mysql.com/doc/refman/5.0/en/dynamic-system-variables.html):

log_queries_not_using_indexes 	boolean 	GLOBAL

log_queries_not_using_indexes system variable is dynamic and can be changed with SET GLOBAL. The value can be really changed, but it does not change server behaviour. 

Look:

openxs@suse:~/dbs/5.0> bin/mysqld_safe --log-slow-queries &
[1] 7418
openxs@suse:~/dbs/5.0> Starting mysqld daemon with databases from /home/openxs/d
bs/5.0/var

openxs@suse:~/dbs/5.0> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.44-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'log%';
+---------------------------------+-------+
| Variable_name                   | Value |
+---------------------------------+-------+
| log                             | OFF   |
| log_bin                         | OFF   |
| log_bin_trust_function_creators | OFF   |
| log_error                       |       |
| log_queries_not_using_indexes   | ON    |
| log_slave_updates               | OFF   |
| log_slow_queries                | ON    |
| log_warnings                    | 1     |
+---------------------------------+-------+
8 rows in set (0.01 sec)

mysql> show create table tab1\G
*************************** 1. row ***************************
       Table: tab1
Create Table: CREATE TABLE `tab1` (
  `c1` int(11) default NULL,
  `c2` char(20) default NULL,
  `c3` char(20) default NULL,
  KEY `k1` (`c2`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> select * from tab1;
+------+--------+--------+
| c1   | c2     | c3     |
+------+--------+--------+
|    1 | hello  | world  |
|    2 | hello2 | world2 |
|    3 | hello3 | world3 |
+------+--------+--------+
3 rows in set (0.00 sec)

mysql> explain select * from tab1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: tab1
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 3
        Extra:
1 row in set (0.00 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.0> tail var/suse-slow.log
/home/openxs/dbs/5.0/libexec/mysqld, Version: 5.0.44-debug-log (Source distribut
ion). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
openxs@suse:~/dbs/5.0> bin/mysqladmin -uroot shutdown
STOPPING server from pid file /home/openxs/dbs/5.0/var/suse.pid
070531 12:55:10  mysqld ended

[1]+  Done                    bin/mysqld_safe --log-slow-queries
openxs@suse:~/dbs/5.0> bin/mysqld_safe --log-slow-queries --log-queries-not-using-indexes &
[1] 7458
openxs@suse:~/dbs/5.0> Starting mysqld daemon with databases from /home/openxs/d
bs/5.0/var

openxs@suse:~/dbs/5.0> bin/mysql -uroot test ies
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.44-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> select * from tab1;
+------+--------+--------+
| c1   | c2     | c3     |
+------+--------+--------+
|    1 | hello  | world  |
|    2 | hello2 | world2 |
|    3 | hello3 | world3 |
+------+--------+--------+
3 rows in set (0.00 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.0> tail var/suse-slow.log
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
/home/openxs/dbs/5.0/libexec/mysqld, Version: 5.0.44-debug-log (Source distribut
ion). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 070531 12:55:20
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 3  Rows_examined: 3
use test;
select * from tab1;

So, this option owrks only if it is set at server's startup.

How to repeat:
1. Start server with slow log enabled but log_queries_not_using_indexes disabled.

2. Execute:

CREATE TABLE `tab1` (
  `c1` int(11) default NULL,
  `c2` char(20) default NULL,
  `c3` char(20) default NULL,
  KEY `k1` (`c2`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1;
INSERT INTO tab1 values(1, "hello", "world");
INSERT INTO tab1 values(2, "hello2", "world2");
INSERT INTO tab1 values(3, "hello3", "world3");
show variables like 'log%';
set global log_queries_not_using_indexes=1;
show variables like 'log%';
select * from tab1;

3. Check slow query log.

Suggested fix:
Take this variable into account when the value is changed with SET GLOBAL (or make it not dynamic and document properly).
[26 Jun 2007 15:18] MySQL Verification Team
in 5.0.24a if you start server with --log-slow-queries and then dynamically set log_queries_not_using_indexes to 1, queries still aren't logged to slow query log that don't use index.
[26 Jun 2007 20:29] Harrison Fisk
Patch to make log-slow-queries-not-using-indexes setable on SESSION or GLOBAL

Attachment: log_queries_not_using_indexes.diff (application/octet-stream, text), 2.58 KiB.

[26 Jun 2007 20:31] Harrison Fisk
The attached patch was done against 5.1-bk since it technically changes the behavior.  It should be trivial to backport if neccesary as it only changes ~4 lines.
[5 Jul 2007 10:34] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30363

ChangeSet@1.2519, 2007-07-05 15:34:12+05:00, ramil@mysql.com +5 -0
  Fix for bug #28808: log_queries_not_using_indexes variable dynamic change is ignored
  
  Problem: logging queries not using indexes we check a special flag which 
  is set only at the server startup and is not changing with a corresponding
  server variable together.
  
  Fix: check the variable value instead of the flag.
[10 Jul 2007 13:27] Bugs System
Pushed into 5.1.21-beta
[10 Jul 2007 13:28] Bugs System
Pushed into 5.0.46
[10 Jul 2007 22:14] Paul DuBois
Noted in 5.0.46, 5.1.21 changelogs.

Runtime changes to the log_queries_not_using_indexes system variable
were ignored.
[24 Jul 2007 6:09] Sveta Smirnova
Bug #29995 was marked as duplicate of this one