Bug #29285 --log-slow-queries + --log-queries-not-using-indexes works incorrect
Submitted: 21 Jun 2007 20:32 Modified: 25 Aug 2008 10:01
Reporter: Valeriy Kravchuk Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:5.0.36, 5.0.37, 5.0.60 OS:Any ((Linux, Windows))
Assigned to: Tatiana Azundris Nuernberg CPU Architecture:Any

[21 Jun 2007 20:32] Valeriy Kravchuk
Description:
Some queries are written to the slow log even when they are NOT slow, returns zero rows and have perfect execution plan where indexes are used for all the tables involved:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot test -P3308
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.0.37-community-nt-log MySQL Community Edition (GPL)

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

mysql> show variables like 'log%';
+---------------------------------+--------------------+
| Variable_name                   | Value              |
+---------------------------------+--------------------+
| log                             | OFF                |
| log_bin                         | OFF                |
| log_bin_trust_function_creators | OFF                |
| log_error                       | .\toshiba-user.err |
| 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> SELECT t1.JDOID, t1.ADMIN_JDOID, t1.CODE, t1.NAME0, t1.PASSWORD, t0.GROUP
_JDOID FROM ipmask t0 LEFT OUTER JOIN group0 t1 ON t0.GROUP_JDOID = t1.JDOID WHE
RE (t0.IPMASK1 = '220.181.19' OR t0.IPMASK1 = '220.181.19.187') GROUP BY t0.GROU
P_JDOID;
Empty set (0.00 sec)

mysql> explain SELECT t1.JDOID, t1.ADMIN_JDOID, t1.CODE, t1.NAME0, t1.PASSWORD,
t0.GROUP_JDOID FROM ipmask t0 LEFT OUTER JOIN group0 t1 ON t0.GROUP_JDOID = t1.J
DOID WHERE (t0.IPMASK1 = '220.181.19' OR t0.IPMASK1 = '220.181.19.187') GROUP BY
 t0.GROUP_JDOID;
+----+-------------+-------+--------+-------------------+----------------+------
---+---------------------+------+--------------------------+
| id | select_type | table | type   | possible_keys     | key            | key_l
en | ref                 | rows | Extra                    |
+----+-------------+-------+--------+-------------------+----------------+------
---+---------------------+------+--------------------------+
|  1 | SIMPLE      | t0    | index  | IPMASK1,IPMASK1_2 | I_IPMASK_GROUP | 19
   | NULL                |    2 | Using where; Using index |
|  1 | SIMPLE      | t1    | eq_ref | PRIMARY           | PRIMARY        | 2
   | test.t0.GROUP_JDOID |    1 |                          |
+----+-------------+-------+--------+-------------------+----------------+------
---+---------------------+------+--------------------------+
2 rows in set (0.00 sec)

Still, we have in slow log:

C:\Program Files\MySQL\MySQL Server 5.0\bin\mysqld-nt, Version: 5.0.37-community
-nt-log (MySQL Community Edition (GPL)). started with:
TCP Port: 3308, Named Pipe: (null)
Time                 Id Command    Argument
# Time: 070621 22:23:38
# User@Host: root[root] @ localhost [127.0.0.1]
# Query_time: 0  Lock_time: 0  Rows_sent: 0  Rows_examined: 2
use test;
SELECT t1.JDOID, t1.ADMIN_JDOID, t1.CODE, t1.NAME0, t1.PASSWORD, t0.GROUP_JDOID
FROM ipmask t0 LEFT OUTER JOIN group0 t1 ON t0.GROUP_JDOID = t1.JDOID WHERE (t0.
IPMASK1 = '220.181.19' OR t0.IPMASK1 = '220.181.19.187') GROUP BY t0.GROUP_JDOID
;

This adds useless information to slow query log and make identification of really problematic queries more difficult.

How to repeat:
See private comment.

Suggested fix:
This is already fixed, it seems, in 5.0.46-BK, but I'd suggest to add a test to prevent regression bugs like this.
[7 Apr 2008 7:01] Tatiana Azundris Nuernberg
I see this behaviour as consistent across all servers (5.0.3x, 5.0-bk, 5.1-bk). It is --log-queries-not-using-indexes that produces these log-entries; while the query produces no result set and is not, in fact, slow, SERVER_QUERY_NO_INDEX_USED is set in sql_select.cc:make_join_readinfo() (around 6221) as we have JT_ALL, which is pretty bad. By that token, the query should show up as optimizable (not in general as "slow" because the execution wasn't, but as "generally optimizable," (we need to traverse all rows, in index or in data ...) which was requested with --l/q/n/u/i). I checked with consulting and got "If that weren't how we're already doing it, it's how we should be doing it. We need that in the field."
[22 Aug 2008 0:37] Trent Lloyd
Here is another example query that appears to trigger this:

 SELECT * FROM table ORDER BY indexed_field LIMIT 1;

I believe this should be relatively well optimized - however it shows up also.  Any further consensus on this issue? Certainly it goes against the specific definition, as EXPLAIN show it USING INDEX much like Valeriy's case.
[22 Aug 2008 3:50] Valeriy Kravchuk
Looks like this is NOT fixed (and there is NO QA test, as I demanded). Newer versions are affected.
[25 Aug 2008 10:01] Sergei Golubchik
As Tatjana has explained, --log-queries-not-using-indexes logs all queries that don't use an index to limit the number of rows, in other words it logs all queries that are expected to retrieve all rows from the table. "Using index" in the EXPLAIN does not count, it does not necessarily mean that index is used to limit the number of rows, it could also mean full index scan.