MySQL Bugs: #46454: MySQL wrong index optimisation leads to incorrect result & crashes

Bug #46454	MySQL wrong index optimisation leads to incorrect result & crashes
Submitted:	29 Jul 2009 16:30	Modified:	14 Sep 2009 19:49
Reporter:	jocelyn fournier (Silver Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S1 (Critical)
Version:	5.1.36, 5.1.38-bzr	OS:	Any
Assigned to:	Martin Hansson	CPU Architecture:	Any
Tags:	qc, regression

Description:
Hi,

For a specific query, MySQL choose to scan only the index file but with the wrong index, which lead to incorrect result in the query.

Could be somehow related to http://bugs.mysql.com/bug.php?id=36817 ?

How to repeat:
First download and inject http://www.mesdiscussions.net/bug.tar.gz in test DB (19 MB)

Then 

use test;
EXPLAIN SELECT id_user FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+----+-------------+-------+-------+-------------------------+-------------+---------+------+-------+--------------------------+
| id | select_type | table | type  | possible_keys           | key         | key_len | ref  | rows  | Extra                    |
+----+-------------+-------+-------+-------------------------+-------------+---------+------+-------+--------------------------+
|  1 | SIMPLE      | ud    | range | id_friend_3,id_friend_4 | id_friend_3 | 3       | NULL | 37974 | Using where; Using index |
+----+-------------+-------+-------+-------------------------+-------------+---------+------+-------+--------------------------+

Here you can see MySQL chooses to user id_friend_3 index to return the result.
However, id_friend_3 does *not* contain id_user (it's id_friend_4 which does) :

 CREATE TABLE `users_logs` (
  `id_user` mediumint(8) unsigned NOT NULL DEFAULT '0',
  `id_friend` mediumint(10) unsigned NOT NULL DEFAULT '0',
  `id_log` int(10) unsigned NOT NULL DEFAULT '0',
  `date` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  PRIMARY KEY (`id_log`,`id_user`,`id_friend`),
  KEY `id_friend_3` (`id_friend`,`date`),
  KEY `id_friend_4` (`id_friend`,`id_user`,`date`),
  KEY `id_friend_5` (`id_user`,`date`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8

Hence, the query leads to a completely incorrect result :

mysql> SELECT id_user FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+---------+
| id_user |
+---------+
|       0 |
|       0 |
|       0 |
|       0 |
|       0 |
|       0 |
|       0 |
|       0 |
|       0 |
+---------+
9 rows in set (0.00 sec)

Adding a field not in id_friend_4 index solve the issue : 

EXPLAIN SELECT id_user,id_log FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+----+-------------+-------+------+-------------------------+-------------+---------+-------+-------+-------------+
| id | select_type | table | type | possible_keys           | key         | key_len | ref   | rows  | Extra       |
+----+-------------+-------+------+-------------------------+-------------+---------+-------+-------+-------------+
|  1 | SIMPLE      | ud    | ref  | id_friend_3,id_friend_4 | id_friend_3 | 3       | const | 37974 | Using where |
+----+-------------+-------+------+-------------------------+-------------+---------+-------+-------+-------------+
1 row in set (0.00 sec)

=> no more Using index here.

SELECT id_user,id_log FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+---------+----------+
| id_user | id_log   |
+---------+----------+
| 4613617 | 10749620 |
| 4613617 | 10749489 |
| 4107676 | 10749404 |
| 4613617 | 10749388 |
| 3928150 | 10749103 |
| 4652634 | 10749047 |
| 4107676 | 10748939 |
| 4470248 | 10748818 |
| 4470248 | 10748797 |
+---------+----------+
9 rows in set (0.00 sec)

query is ok now

Regards,
  Jocelyn Fournier

Hi,

Actually, I've found out an even more problematic query which crashes the server : 

SELECT DISTINCT id_user FROM users_logs WHERE id_friend=4299422 ORDER BY date DESC LIMIT 0, 9;
ERROR 2013 (HY000): Lost connection to MySQL server during query

Stack trace : 

090729 18:43:55 - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=268435456
read_buffer_size=524288
max_used_connections=4
max_threads=200
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 468217 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x87aa198
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0xa31923c8 thread_stack 0x30000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x21)[0x84da8c1]
/usr/local/mysql/bin/mysqld(handle_segfault+0x381)[0x82029b1]
[0xffffe420]
/usr/local/mysql/bin/mysqld[0x8273a93]
/usr/local/mysql/bin/mysqld(_ZN4JOIN8optimizeEv+0x2494)[0x8279964]
/usr/local/mysql/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x72)[0x827b0f2]
/usr/local/mysql/bin/mysqld(_Z13handle_selectP3THDP6st_lexP13select_resultm+0x15e)[0x8280bee]
/usr/local/mysql/bin/mysqld[0x820fb00]
/usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0x4157)[0x82166c7]
/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x340)[0x8219f40]
/usr/local/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x11e0)[0x821b130]
/usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0xe0)[0x821b9b0]
/usr/local/mysql/bin/mysqld(handle_one_connection+0x253)[0x820c2d3]
/lib/libpthread.so.0[0xb7ed5f3b]
/lib/libc.so.6(clone+0x5e)[0xb7de8bee]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x87fba10 = SELECT DISTINCT id_user FROM users_logs WHERE id_friend=4299422 ORDER BY date DESC LIMIT 0, 9
thd->thread_id=22
thd->killed=NOT_KILLED

Hence setting severity the critical.

Regards,

Thank you for the bug report. Verified just as described with recent 5.1.38 from bzr:

valeriy-kravchuks-macbook-pro:5.1 openxs$ bin/mysql -uroot test < ~/Downloads/bug.sql 
valeriy-kravchuks-macbook-pro:5.1 openxs$ bin/mysql -uroot testReading 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 10
Server version: 5.1.38-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show create table user_logs\G
ERROR 1146 (42S02): Table 'test.user_logs' doesn't exist
mysql> show create table users_logs\G
*************************** 1. row ***************************
       Table: users_logs
Create Table: CREATE TABLE `users_logs` (
  `id_user` mediumint(8) unsigned NOT NULL DEFAULT '0',
  `id_friend` mediumint(10) unsigned NOT NULL DEFAULT '0',
  `id_log` int(10) unsigned NOT NULL DEFAULT '0',
  `date` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  PRIMARY KEY (`id_log`,`id_user`,`id_friend`),
  KEY `id_friend_3` (`id_friend`,`date`),
  KEY `id_friend_4` (`id_friend`,`id_user`,`date`),
  KEY `id_friend_5` (`id_user`,`date`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8
1 row in set (0.01 sec)

mysql>  SELECT id_user FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date
    -> DESC LIMIT 0, 9;
+---------+
| id_user |
+---------+
|       0 | 
|       0 | 
|       0 | 
|       0 | 
|       0 | 
|       0 | 
|       0 | 
|       0 | 
|       0 | 
+---------+
9 rows in set (0.00 sec)

mysql> explain SELECT id_user FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+----+-------------+-------+-------+-------------------------+-------------+---------+------+-------+--------------------------+
| id | select_type | table | type  | possible_keys           | key         | key_len | ref  | rows  | Extra                    |
+----+-------------+-------+-------+-------------------------+-------------+---------+------+-------+--------------------------+
|  1 | SIMPLE      | ud    | range | id_friend_3,id_friend_4 | id_friend_3 | 3       | NULL | 37974 | Using where; Using index | 
+----+-------------+-------+-------+-------------------------+-------------+---------+------+-------+--------------------------+
1 row in set (0.00 sec)

mysql> SELECT id_user FROM users_logs ud FORCE INDEX(id_friend_4) WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+---------+
| id_user |
+---------+
| 4613617 | 
| 4613617 | 
| 4107676 | 
| 4613617 | 
| 3928150 | 
| 4652634 | 
| 4107676 | 
| 4470248 | 
| 4470248 | 
+---------+
9 rows in set (0.13 sec)

mysql> explain SELECT id_user FROM users_logs ud FORCE INDEX(id_friend_4) WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+----+-------------+-------+------+---------------+-------------+---------+-------+-------+------------------------------------------+
| id | select_type | table | type | possible_keys | key         | key_len | ref   | rows  | Extra                                    |
+----+-------------+-------+------+---------------+-------------+---------+-------+-------+------------------------------------------+
|  1 | SIMPLE      | ud    | ref  | id_friend_4   | id_friend_4 | 3       | const | 38254 | Using where; Using index; Using filesort | 
+----+-------------+-------+------+---------------+-------------+---------+-------+-------+------------------------------------------+
1 row in set (0.00 sec)
 
This is a very serious bug.

5.0.85 works properly, so this is a regression:

valeriy-kravchuks-macbook-pro:5.0 openxs$ bin/mysql -uroot testReading 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 3
Server version: 5.0.85 Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SELECT id_user FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+---------+
| id_user |
+---------+
| 4613617 | 
| 4613617 | 
| 4107676 | 
| 4613617 | 
| 3928150 | 
| 4652634 | 
| 4107676 | 
| 4470248 | 
| 4470248 | 
+---------+
9 rows in set (0.40 sec)

mysql> explain SELECT id_user FROM users_logs ud WHERE ud.id_friend = 4299422 ORDER BY ud.date DESC LIMIT 0, 9;
+----+-------------+-------+------+-------------------------+-------------+---------+-------+-------+------------------------------------------+
| id | select_type | table | type | possible_keys           | key         | key_len | ref   | rows  | Extra                                    |
+----+-------------+-------+------+-------------------------+-------------+---------+-------+-------+------------------------------------------+
|  1 | SIMPLE      | ud    | ref  | id_friend_3,id_friend_4 | id_friend_4 | 3       | const | 38254 | Using where; Using index; Using filesort | 
+----+-------------+-------+------+-------------------------+-------------+---------+-------+-------+------------------------------------------+
1 row in set (0.01 sec)

And 5.0 do not crash with your other query:

mysql> SELECT DISTINCT id_user FROM users_logs WHERE id_friend=4299422 ORDER BY date DESC LIMIT
    -> 0, 9;
+---------+
| id_user |
+---------+
| 4652634 | 
| 4761862 | 
| 4736262 | 
| 4180236 | 
| 4189646 | 
| 4889298 | 
| 4658780 | 
| 4394556 | 
| 4194404 | 
+---------+
9 rows in set (0.02 sec)

mysql> select version();
+-----------+
| version() |
+-----------+
| 5.0.85    | 
+-----------+
1 row in set (0.00 sec)

Unlike 5.1.38:

valeriy-kravchuks-macbook-pro:5.1 openxs$ 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.1.38-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SELECT DISTINCT id_user FROM users_logs WHERE id_friend=4299422 ORDER BY date DESC LIMIT 0, 9;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> 090729 19:59:47 mysqld_safe mysqld restarted

And nothing can prevent this crash, so there is no (good) workaround for your it.

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/80174

3062 Martin Hansson	2009-08-05
      Bug#46454: MySQL wrong index optimisation leads to incorrect result & crashes
      
      When the 'Using index' optimization is used, the optimizer may still - after
      cost-based optimization - decide to use another index in order to avoid using
      a temporary table. But when this happens, the flag to the storage engine to 
      read index only (not table) was still set. Fixed by resetting the flag in the 
      storage engine and TABLE structure in the above scenario, unless the new index
      allows for the same optimization.
     @ mysql-test/r/order_by.result
        Bug#46454: Test result.
     @ mysql-test/t/order_by.test
        Bug#46454: Test case.
     @ sql/sql_select.cc
        Bug#46454: Fix. Removed code which would a duplicate.
     @ sql/table.h
        Bug#46454: Added comment to field.

Bug#46583 has been filed to address the problem with 

SELECT DISTINCT id_user FROM users_logs WHERE id_friend=4299422 ORDER BY date DESC LIMIT
0, 9;

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/80339

3062 Martin Hansson	2009-08-07
      Bug#46454: MySQL wrong index optimisation leads to incorrect result & crashes
      
      When the 'Using index' optimization is used, the optimizer may still - after
      cost-based optimization - decide to use another index in order to avoid using
      a temporary table. But when this happens, the flag to the storage engine to 
      read index only (not table) was still set. Fixed by resetting the flag in the 
      storage engine and TABLE structure in the above scenario, unless the new index
      allows for the same optimization.
     @ mysql-test/r/order_by.result
        Bug#46454: Test result.
     @ mysql-test/t/order_by.test
        Bug#46454: Test case.
     @ sql/sql_select.cc
        Bug#46454: Fix. Removed code which would be a duplicate.
     @ sql/table.h
        Bug#46454: Added comment to field.

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/80346

3062 Martin Hansson	2009-08-07
      Bug#46454: MySQL wrong index optimisation leads to incorrect result & crashes
      Problem 1:
      When the 'Using index' optimization is used, the optimizer may still - after
      cost-based optimization - decide to use another index in order to avoid using
      a temporary table. But when this happens, the flag to the storage engine to 
      read index only (not table) was still set. Fixed by resetting the flag in the 
      storage engine and TABLE structure in the above scenario, unless the new index
      allows for the same optimization.
      Problem 2:
      When a 'ref' access method was employed by cost-based optimizer, (when the column
      is non-NULLable), it was assumed that it needed no initialization if 'quick' access
      methods (since they are based on range scan). When ORDER BY optimization overrides 
      the decision, however, it expects to have this initialized and hence crashes. 
      Fixed in 5.1 (was fixed in 6.0 already) by initializing 'quick' even when there's 
      'ref' access. 
     @ mysql-test/r/order_by.result
        Bug#46454: Test result.
     @ mysql-test/t/order_by.test
        Bug#46454: Test case.
     @ sql/sql_select.cc
        Bug#46454: 
        Problem 1 fixed in make_join_select()
        Problem 2 fixed in test_if_skip_sort_order()
     @ sql/table.h
        Bug#46454: Added comment to field.

Pushed into 5.1.38 (revid:davi.arnaut@sun.com-20090811142907-uu7nckpe93pii81v) (version source revid:davi.arnaut@sun.com-20090811142907-uu7nckpe93pii81v) (merge vers: 5.1.38) (pib:11)

Noted in 5.1.38 changelog.

Incorrect index optimization could lead to incorrect results or
server crashes.

Setting report to NDI pending push into 5.4.x.

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090914155317-m1g9wodmndzdj4l1) (version source revid:alik@sun.com-20090914155317-m1g9wodmndzdj4l1) (merge vers: 5.4.4-alpha) (pib:11)

Noted in 5.4.4 changelog.

Pushed into 5.1.39-ndb-6.3.28 (revid:jonas@mysql.com-20091001055605-ap2kiaarr7p40mmv) (version source revid:jonas@mysql.com-20091001055605-ap2kiaarr7p40mmv) (merge vers: 5.1.39-ndb-6.3.28) (pib:11)

Pushed into 5.1.39-ndb-7.0.9 (revid:jonas@mysql.com-20091001072547-kv17uu06hfjhgjay) (version source revid:jonas@mysql.com-20091001071652-irejtnumzbpsbgk2) (merge vers: 5.1.39-ndb-7.0.9) (pib:11)

Pushed into 5.1.39-ndb-7.1.0 (revid:jonas@mysql.com-20091001123013-g9ob2tsyctpw6zs0) (version source revid:jonas@mysql.com-20091001123013-g9ob2tsyctpw6zs0) (merge vers: 5.1.39-ndb-7.1.0) (pib:11)

Pushed into 5.1.39-ndb-6.2.19 (revid:jonas@mysql.com-20091005103850-dwij2dojwpvf5hi6) (version source revid:jonas@mysql.com-20090930185117-bhud4ek1y0hsj1nv) (merge vers: 5.1.39-ndb-6.2.19) (pib:11)

The 5.4 fix has been pushed to 5.4.2.