Description:
For queries with HAVING clause EXPLAIN may not show real plan used (suggesting other one). This makes troubleshooting more complex.
Here is a simplified example (based on real life case where query execution time was very different, while EXPLAIN had not let to see why), on MySQL 5.5.30. (In reality it was Percona Server 5.1.58, but as one can check we have upstream EXPLAIN problem here even in 5.5.30 and 5.6.10, hence my report):
C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3312 test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 17
Server version: 5.5.30 MySQL Community Server (GPL)
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> show create table t1\G
*************************** 1. row ***************************
Table: t1
Create Table: CREATE TABLE `t1` (
`id1` bigint(20) NOT NULL,
`id2` bigint(20) NOT NULL,
`id3` bigint(20) NOT NULL,
`c1` bigint(20) DEFAULT NULL,
`c2` bigint(20) NOT NULL,
`seqid` bigint(20) NOT NULL AUTO_INCREMENT,
`time_stamp` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
PRIMARY KEY (`id1`,`id2`),
UNIQUE KEY `ix_seq` (`seqid`),
KEY `ix_ts` (`time_stamp`)
) ENGINE=InnoDB AUTO_INCREMENT=1782 DEFAULT CHARSET=utf8
1 row in set (0.00 sec)
mysql> select count(*) from t1 where time_stamp BETWEEN '2013-03-18 17:00:00' AN
D '2013-03-31 22:00:00';
+----------+
| count(*) |
+----------+
| 579 |
+----------+
1 row in set (0.00 sec)
mysql> select count(*) from t1;
+----------+
| count(*) |
+----------+
| 1024 |
+----------+
1 row in set (0.00 sec)
So, for this specific table and data (see dump attached), we have:
mysql> EXPLAIN
-> SELECT * FROM t1 o WHERE o.id3 = 100
-> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
-> ORDER BY o.seqid limit 10;
+----+-------------+-------+-------+---------------+--------+---------+------+--
----+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | r
ows | Extra |
+----+-------------+-------+-------+---------------+--------+---------+------+--
----+-------------+
| 1 | SIMPLE | o | index | ix_ts | ix_seq | 8 | NULL |
17 | Using where |
+----+-------------+-------+-------+---------------+--------+---------+------+--
----+-------------+
1 row in set (0.00 sec)
mysql> EXPLAIN
-> SELECT * FROM t1 o WHERE o.id3 = 100
-> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
-> ORDER BY o.seqid+0 limit 10;
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | ro
ws | Extra |
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
| 1 | SIMPLE | o | range | ix_ts | ix_ts | 4 | NULL | 5
78 | Using where; Using filesort |
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
1 row in set (0.00 sec)
that is, different plans for queries, and for a reason - o.seqid+0 in the query is used in purpose, to make server NOT use index on sequid column (that it likes to use very much because of PRDER By with small LIMIT of rows selected).
Now, let's add HAVING c2 > 0 (this condition is actually true for all rows in the table), and we'll see plans are reported as the same now:
mysql> EXPLAIN
-> SELECT * FROM t1 o WHERE o.id3 = 100
-> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
-> HAVING c2 > 0
-> ORDER BY o.seqid limit 10;
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | ro
ws | Extra |
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
| 1 | SIMPLE | o | range | ix_ts | ix_ts | 4 | NULL | 5
78 | Using where; Using filesort |
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
1 row in set (0.00 sec)
mysql> EXPLAIN
-> SELECT * FROM t1 o WHERE o.id3 = 100
-> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
-> HAVING c2 > 0
-> ORDER BY o.seqid+0 limit 10;
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | ro
ws | Extra |
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
| 1 | SIMPLE | o | range | ix_ts | ix_ts | 4 | NULL | 5
78 | Using where; Using filesort |
+----+-------------+-------+-------+---------------+-------+---------+------+---
---+-----------------------------+
1 row in set (0.00 sec)
But then let's check Handler_read% after execution of each query:
mysql> flush status;
Query OK, 0 rows affected (0.00 sec)
mysql> SELECT * FROM t1 o WHERE o.id3 = 100
-> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
-> HAVING c2 > 0
-> ORDER BY o.seqid limit 10;
+------+------+-----+------+----+-------+---------------------+
| id1 | id2 | id3 | c1 | c2 | seqid | time_stamp |
+------+------+-----+------+----+-------+---------------------+
| 4386 | 8408 | 100 | NULL | 10 | 1270 | 2013-03-18 19:00:00 |
...
| 8119 | 739 | 100 | NULL | 10 | 1279 | 2013-03-18 19:00:00 |
+------+------+-----+------+----+-------+---------------------+
10 rows in set (0.38 sec)
mysql> show status like 'Handler_read%';
+-----------------------+-------+
| Variable_name | Value |
+-----------------------+-------+
| Handler_read_first | 1 |
| Handler_read_key | 1 |
| Handler_read_last | 0 |
| Handler_read_next | 521 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 0 |
+-----------------------+-------+
7 rows in set (0.00 sec)
mysql> flush status;
Query OK, 0 rows affected (0.00 sec)
mysql> SELECT * FROM t1 o WHERE o.id3 = 100
-> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
-> HAVING c2 > 0
-> ORDER BY o.seqid+0 limit 10;
+------+------+-----+------+----+-------+---------------------+
| id1 | id2 | id3 | c1 | c2 | seqid | time_stamp |
+------+------+-----+------+----+-------+---------------------+
| 4386 | 8408 | 100 | NULL | 10 | 1270 | 2013-03-18 19:00:00 |
...
| 8119 | 739 | 100 | NULL | 10 | 1279 | 2013-03-18 19:00:00 |
+------+------+-----+------+----+-------+---------------------+
10 rows in set (0.01 sec)
mysql> show status like 'Handler_read%';
+-----------------------+-------+
| Variable_name | Value |
+-----------------------+-------+
| Handler_read_first | 0 |
| Handler_read_key | 1 |
| Handler_read_last | 0 |
| Handler_read_next | 579 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 0 |
+-----------------------+-------+
7 rows in set (0.00 sec)
Obviously different plans were used, in the first case we still had "index" scan on ix_seq. On larger and real life data sets this has bad performance consequences, and EXPLAIN with its misleading information makes troubleshooting more complex.
How to repeat:
Load the dump attached, then check EXPLAIN results and Handler_read% values for the following queries:
SELECT * FROM t1 o WHERE o.id3 = 100
AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
HAVING c2 > 0
ORDER BY o.seqid limit 10;
SELECT * FROM t1 o WHERE o.id3 = 100
AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00'
HAVING c2 > 0
ORDER BY o.seqid+0 limit 10;
Suggested fix:
Do something with EXPLAIN to show real plan used in this case (or, even better, make server use the plan EXPLAIN shows for the case with HAVING and +0 in ORDER BY :).
Description: For queries with HAVING clause EXPLAIN may not show real plan used (suggesting other one). This makes troubleshooting more complex. Here is a simplified example (based on real life case where query execution time was very different, while EXPLAIN had not let to see why), on MySQL 5.5.30. (In reality it was Percona Server 5.1.58, but as one can check we have upstream EXPLAIN problem here even in 5.5.30 and 5.6.10, hence my report): C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3312 test Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 17 Server version: 5.5.30 MySQL Community Server (GPL) Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> show create table t1\G *************************** 1. row *************************** Table: t1 Create Table: CREATE TABLE `t1` ( `id1` bigint(20) NOT NULL, `id2` bigint(20) NOT NULL, `id3` bigint(20) NOT NULL, `c1` bigint(20) DEFAULT NULL, `c2` bigint(20) NOT NULL, `seqid` bigint(20) NOT NULL AUTO_INCREMENT, `time_stamp` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00', PRIMARY KEY (`id1`,`id2`), UNIQUE KEY `ix_seq` (`seqid`), KEY `ix_ts` (`time_stamp`) ) ENGINE=InnoDB AUTO_INCREMENT=1782 DEFAULT CHARSET=utf8 1 row in set (0.00 sec) mysql> select count(*) from t1 where time_stamp BETWEEN '2013-03-18 17:00:00' AN D '2013-03-31 22:00:00'; +----------+ | count(*) | +----------+ | 579 | +----------+ 1 row in set (0.00 sec) mysql> select count(*) from t1; +----------+ | count(*) | +----------+ | 1024 | +----------+ 1 row in set (0.00 sec) So, for this specific table and data (see dump attached), we have: mysql> EXPLAIN -> SELECT * FROM t1 o WHERE o.id3 = 100 -> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' -> ORDER BY o.seqid limit 10; +----+-------------+-------+-------+---------------+--------+---------+------+-- ----+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | r ows | Extra | +----+-------------+-------+-------+---------------+--------+---------+------+-- ----+-------------+ | 1 | SIMPLE | o | index | ix_ts | ix_seq | 8 | NULL | 17 | Using where | +----+-------------+-------+-------+---------------+--------+---------+------+-- ----+-------------+ 1 row in set (0.00 sec) mysql> EXPLAIN -> SELECT * FROM t1 o WHERE o.id3 = 100 -> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' -> ORDER BY o.seqid+0 limit 10; +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | ro ws | Extra | +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ | 1 | SIMPLE | o | range | ix_ts | ix_ts | 4 | NULL | 5 78 | Using where; Using filesort | +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ 1 row in set (0.00 sec) that is, different plans for queries, and for a reason - o.seqid+0 in the query is used in purpose, to make server NOT use index on sequid column (that it likes to use very much because of PRDER By with small LIMIT of rows selected). Now, let's add HAVING c2 > 0 (this condition is actually true for all rows in the table), and we'll see plans are reported as the same now: mysql> EXPLAIN -> SELECT * FROM t1 o WHERE o.id3 = 100 -> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' -> HAVING c2 > 0 -> ORDER BY o.seqid limit 10; +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | ro ws | Extra | +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ | 1 | SIMPLE | o | range | ix_ts | ix_ts | 4 | NULL | 5 78 | Using where; Using filesort | +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ 1 row in set (0.00 sec) mysql> EXPLAIN -> SELECT * FROM t1 o WHERE o.id3 = 100 -> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' -> HAVING c2 > 0 -> ORDER BY o.seqid+0 limit 10; +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | ro ws | Extra | +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ | 1 | SIMPLE | o | range | ix_ts | ix_ts | 4 | NULL | 5 78 | Using where; Using filesort | +----+-------------+-------+-------+---------------+-------+---------+------+--- ---+-----------------------------+ 1 row in set (0.00 sec) But then let's check Handler_read% after execution of each query: mysql> flush status; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM t1 o WHERE o.id3 = 100 -> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' -> HAVING c2 > 0 -> ORDER BY o.seqid limit 10; +------+------+-----+------+----+-------+---------------------+ | id1 | id2 | id3 | c1 | c2 | seqid | time_stamp | +------+------+-----+------+----+-------+---------------------+ | 4386 | 8408 | 100 | NULL | 10 | 1270 | 2013-03-18 19:00:00 | ... | 8119 | 739 | 100 | NULL | 10 | 1279 | 2013-03-18 19:00:00 | +------+------+-----+------+----+-------+---------------------+ 10 rows in set (0.38 sec) mysql> show status like 'Handler_read%'; +-----------------------+-------+ | Variable_name | Value | +-----------------------+-------+ | Handler_read_first | 1 | | Handler_read_key | 1 | | Handler_read_last | 0 | | Handler_read_next | 521 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 0 | +-----------------------+-------+ 7 rows in set (0.00 sec) mysql> flush status; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM t1 o WHERE o.id3 = 100 -> AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' -> HAVING c2 > 0 -> ORDER BY o.seqid+0 limit 10; +------+------+-----+------+----+-------+---------------------+ | id1 | id2 | id3 | c1 | c2 | seqid | time_stamp | +------+------+-----+------+----+-------+---------------------+ | 4386 | 8408 | 100 | NULL | 10 | 1270 | 2013-03-18 19:00:00 | ... | 8119 | 739 | 100 | NULL | 10 | 1279 | 2013-03-18 19:00:00 | +------+------+-----+------+----+-------+---------------------+ 10 rows in set (0.01 sec) mysql> show status like 'Handler_read%'; +-----------------------+-------+ | Variable_name | Value | +-----------------------+-------+ | Handler_read_first | 0 | | Handler_read_key | 1 | | Handler_read_last | 0 | | Handler_read_next | 579 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 0 | +-----------------------+-------+ 7 rows in set (0.00 sec) Obviously different plans were used, in the first case we still had "index" scan on ix_seq. On larger and real life data sets this has bad performance consequences, and EXPLAIN with its misleading information makes troubleshooting more complex. How to repeat: Load the dump attached, then check EXPLAIN results and Handler_read% values for the following queries: SELECT * FROM t1 o WHERE o.id3 = 100 AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' HAVING c2 > 0 ORDER BY o.seqid limit 10; SELECT * FROM t1 o WHERE o.id3 = 100 AND o.time_stamp BETWEEN '2013-03-18 17:00:00' AND '2013-03-31 22:00:00' HAVING c2 > 0 ORDER BY o.seqid+0 limit 10; Suggested fix: Do something with EXPLAIN to show real plan used in this case (or, even better, make server use the plan EXPLAIN shows for the case with HAVING and +0 in ORDER BY :).