Description:
In 5.6.20/23 with log_queries_not_using_indexes=ON, queries that use Index Merge (sort_union) get logged to slow query log, even if no rows are actually touched.
The manual states that if rows are filtered by an index, it should not get slow query logged:
=====
If you are using this option with the slow query log enabled, queries that are expected to retrieve all rows are logged. See Section 5.2.5, “The Slow Query Log”. 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.
https://dev.mysql.com/doc/refman/5.6/en/server-options.html#option_mysqld_log-queries-not-...
=====
Tested on 5.6.20 Community and 5.6.23 Enterprise with same results.
How to repeat:
mysql [localhost] {msandbox} (test) > SHOW CREATE TABLE t\G
*************************** 1. row ***************************
Table: t
Create Table: CREATE TABLE `t` (
`id` int(10) NOT NULL AUTO_INCREMENT,
`a` int(10) unsigned DEFAULT NULL,
`b` int(10) unsigned DEFAULT NULL,
`firstdate` datetime NOT NULL,
`lastdate` datetime NOT NULL,
PRIMARY KEY (`id`),
KEY `a` (`a`),
KEY `b` (`b`),
KEY `lastdate` (`lastdate`)
) ENGINE=InnoDB AUTO_INCREMENT=11101 DEFAULT CHARSET=latin1
1 row in set (0.00 sec)
Even though problem happens on empty table too, you can populate the table with random data using this:
shell> for i in $(seq 1 10000) ; do mysql test -e "INSERT INTO t(a,b,firstdate,lastdate) SELECT ceil(rand()*5),ceil(rand()*30), TIMESTAMPADD(SECOND, FLOOR(RAND() * TIMESTAMPDIFF(SECOND, '2010-04-30 14:53:27', NOW())), '2010-04-30 14:53:27'), TIMESTAMPADD(SECOND, FLOOR(RAND() * TIMESTAMPDIFF(SECOND, '2010-04-30 14:53:27', NOW())), '2010-04-30 14:53:27')" ; done
mysql [localhost] {msandbox} (test) > SELECT * FROM t WHERE (a>10 OR b=5);
+-------+------+------+---------------------+---------------------+
| id | a | b | firstdate | lastdate |
+-------+------+------+---------------------+---------------------+
| 23 | 5 | 5 | 2011-09-23 15:24:40 | 2015-03-30 21:15:02 |
<snip>
| 11078 | 1 | 5 | 2011-09-23 04:04:01 | 2014-11-30 22:05:08 |
| 11085 | 5 | 5 | 2010-06-27 19:36:19 | 2013-08-20 02:47:53 |
| 11092 | 4 | 5 | 2013-07-07 07:15:11 | 2014-03-29 08:56:38 |
+-------+------+------+---------------------+---------------------+
383 rows in set (0.01 sec)
mysql [localhost] {msandbox} (test) > EXPLAIN DELETE FROM t WHERE (a>10
OR b=5);
+----+-------------+-------+-------------+---------------+------+---------+------+------+------------------------------------+
| id | select_type | table | type | possible_keys | key |
key_len | ref | rows | Extra |
+----+-------------+-------+-------------+---------------+------+---------+------+------+------------------------------------+
| 1 | SIMPLE | t | index_merge | a,b | a,b |
5,5 | NULL | 384 | Using sort_union(a,b); Using where |
+----+-------------+-------+-------------+---------------+------+---------+------+------+------------------------------------+
1 row in set (0.00 sec)
mysql [localhost] {msandbox} (test) > DELETE FROM t WHERE (a>10 OR b=5);
Query OK, 383 rows affected (0.04 sec)
-- Now we see the query in the slow log
# Time: 150408 20:37:28
# User@Host: msandbox[msandbox] @ localhost [] Id: 20008
# Query_time: 0.043656 Lock_time: 0.000090 Rows_sent: 0 Rows_examined: 383
SET timestamp=1428518248;
DELETE FROM t WHERE (a>10 OR b=5);
-- Even if try again, such that the delete has no rows to operate on, this is still written to slow query log
mysql [localhost] {msandbox} (test) > EXPLAIN DELETE FROM t WHERE (a>10
OR b=5);
+----+-------------+-------+-------------+---------------+------+---------+------+------+------------------------------------+
| id | select_type | table | type | possible_keys | key |
key_len | ref | rows | Extra |
+----+-------------+-------+-------------+---------------+------+---------+------+------+------------------------------------+
| 1 | SIMPLE | t | index_merge | a,b | a,b |
5,5 | NULL | 2 | Using sort_union(a,b); Using where |
+----+-------------+-------+-------------+---------------+------+---------+------+------+------------------------------------+
1 row in set (0.00 sec)
mysql [localhost] {msandbox} (test) > DELETE FROM t WHERE (a>10 OR b=5);
Query OK, 0 rows affected (0.00 sec)
# Time: 150408 20:56:30
# User@Host: msandbox[msandbox] @ localhost [] Id: 20008
# Query_time: 0.000233 Lock_time: 0.000091 Rows_sent: 0 Rows_examined: 0
SET timestamp=1428519390;
DELETE FROM t WHERE (a>10 OR b=5);
Suggested fix:
Do not log queries execution plans that use indexes.
© 2024, Oracle Corporation and/or its affiliates