Bug #38562 Queries mistakenly logged into slow query log
Submitted: 5 Aug 2008 9:36 Modified: 26 Oct 2008 1:06
Reporter: Victoria Reznichenko Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Documentation Severity:S3 (Non-critical)
Version:5.0.66a, 5.1.26-rc, any OS:Any
Assigned to: Paul DuBois CPU Architecture:Any

[5 Aug 2008 9:36] Victoria Reznichenko
Description:
If --log-queries-not-using-indexes option is used, MySQL mistakenly writes queries that actually _use_ indexes for ORDER BY.

For example:

There is a test table:

CREATE TABLE `i` (
  `pk` int(11) NOT NULL auto_increment,
  `dt` timestamp NOT NULL default CURRENT_TIMESTAMP on update CURRENT_TIMESTAMP,
  PRIMARY KEY  (`pk`),
  KEY `dt` (`dt`)
) ENGINE=InnoDB AUTO_INCREMENT=294913 DEFAULT CHARSET=latin1;

and 2 simple queries:
select pk from i order by dt limit 1;
select pk from i order by pk limit 1;

MySQL will use indexes for both queries for ORDER BY and EXPLAIN confirms it:

mysql> explain select pk from i order by dt limit 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: i
         type: index
possible_keys: NULL
          key: dt
      key_len: 4
          ref: NULL
         rows: 295617
        Extra: Using index
1 row in set (0.00 sec)

mysql> explain select pk from i order by pk limit 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: i
         type: index
possible_keys: NULL
          key: PRIMARY
      key_len: 4
          ref: NULL
         rows: 295617
        Extra: Using index
1 row in set (0.00 sec)

However these queries still go to slow query log.

Snip from slow query log:

# Time: 080805 11:29:35
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use test;
select pk from i order by dt limit 1;
# Time: 080805 11:29:38
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
select pk from i order by pk limit 1;

How to repeat:
1. start MySQL with slow query log enabled + log-queries-not-using-indexes

2. create table:
CREATE TABLE `i` (
  `pk` int(11) NOT NULL auto_increment,
  `dt` timestamp NOT NULL default CURRENT_TIMESTAMP on update CURRENT_TIMESTAMP,
  PRIMARY KEY  (`pk`),
  KEY `dt` (`dt`)
) ENGINE=InnoDB AUTO_INCREMENT=294913 DEFAULT CHARSET=latin1;

3. add some dummy data

4. execute SELECTs:

select pk from i order by dt limit 1;
select pk from i order by pk limit 1;

5. check slow query log
[5 Aug 2008 15:14] Valeriy Kravchuk
Thank you for a bug report. Verified just as described on 5.0.66a:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot -P3308 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.66a-enterprise-gpl-nt-log MySQL Enterprise Server (GPL)

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

mysql> CREATE TABLE `i` (
    ->   `pk` int(11) NOT NULL auto_increment,
    ->   `dt` timestamp NOT NULL default CURRENT_TIMESTAMP on update CURRENT_TIM
ESTAMP,
    ->   PRIMARY KEY  (`pk`),
    ->   KEY `dt` (`dt`)
    -> ) ENGINE=InnoDB AUTO_INCREMENT=294913 DEFAULT CHARSET=latin1;
Query OK, 0 rows affected (0.33 sec)

mysql> insert into i (dt) values (now()), ('2008-01-01'), ('2008-02-02');
Query OK, 3 rows affected (0.42 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql> explain select pk from i order by dt limit 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: i
         type: index
possible_keys: NULL
          key: dt
      key_len: 4
          ref: NULL
         rows: 3
        Extra: Using index
1 row in set (0.05 sec)

mysql> explain select pk from i order by pk limit 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: i
         type: index
possible_keys: NULL
          key: PRIMARY
      key_len: 4
          ref: NULL
         rows: 3
        Extra: Using index
1 row in set (0.00 sec)

mysql> select pk from i order by dt limit 1\G
*************************** 1. row ***************************
pk: 294914
1 row in set (0.00 sec)

mysql> select pk from i order by pk limit 1\G
*************************** 1. row ***************************
pk: 294913
1 row in set (0.00 sec)

Indexes are used but queries above are logged into slow log:

C:\Program Files\MySQL\MySQL Server 5.0\bin\mysqld-nt, Version: 5.0.66a-enterpri
se-gpl-nt-log (MySQL Enterprise Server (GPL)). started with:
TCP Port: 3308, Named Pipe: (null)
Time                 Id Command    Argument
# Time: 080805 18:11:28
# User@Host: root[root] @ localhost [127.0.0.1]
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use test;
select pk from i order by dt limit 1;
# Time: 080805 18:11:40
# User@Host: root[root] @ localhost [127.0.0.1]
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
select pk from i order by pk limit 1;
[5 Aug 2008 15:18] Valeriy Kravchuk
5.1.26-rc is also affected.
[24 Oct 2008 0:44] Tatiana Azundris Nuernberg
Docs team:

This is Not A Bug. Since this has come up before however, it seems safe
to call it "unexpected behaviour to some" (and "highly desired behaviour"
to others), so I suggest we make the documentation more elaborate to avoid
confusion (the current behaviour is useful, correct, but somewhat unexpected
given the option's name and the language surrounding it in the server; docs
should provide caveat. Explanation of what happens and why is given in
comments for Bug#29285 ).

thanks, -T-
[26 Oct 2008 0:55] Paul DuBois
Per Tatjiana's comment, recategorizing as Docs bug and assigning to myself.
[26 Oct 2008 1:06] Paul DuBois
Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.

Updated option description:

If you are using this option with the slow query log enabled, queries
that are expected to retrieve all rows are logged. This option does 
not necessarily mean that no index is used. For example, a query that
uses a full index scan uses an index but would be logged because the
index would not limit the number of rows.