Bug #59950 Identical query taking longer on 5.5.8 compared to 5.1
Submitted: 4 Feb 2011 16:23 Modified: 7 Apr 2012 0:14
Reporter: Pavel Baranov Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S5 (Performance)
Version:5.5.8 OS:Linux (centos 5.5 64bit)
Assigned to: CPU Architecture:Any
Tags: Optimizer, regression

[4 Feb 2011 16:23] Pavel Baranov
Description:
ON 5.5.8 : 
mysql> explain extended select STRAIGHT_JOIN p.id from profile_thumbs_name as pt join profiles as p on p.id = pt.profile_id join profile_phones as pp on pp.profile_id = p.id where p.links > -1 order by pt.profile_id desc limit 40; 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra | 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 
| 1 | SIMPLE | pt | index | PRIMARY,profile_thumb | PRIMARY | 4 | NULL | 40 | 58466376.00 | Using index | 
| 1 | SIMPLE | p | eq_ref | PRIMARY,links | PRIMARY | 4 | peekyou.pt.profile_id | 1 | 100.00 | Using where | 
| 1 | SIMPLE | pp | ref | prof_type | prof_type | 4 | peekyou.pt.profile_id | 1 | 100.00 | Using index | 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 

Execution: 40 rows in set (2.58 sec) 

ON 5.5.8 : 
mysql> explain extended select STRAIGHT_JOIN p.id from profile_thumbs_name as pt join profiles as p on p.id = pt.profile_id join profile_phones as pp on pp.profile_id = p.id where p.links > -1 order by pt.profile_id desc limit 40; 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra | 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 
| 1 | SIMPLE | pt | index | PRIMARY,profile_thumb | PRIMARY | 4 | NULL | 40 | 58466376.00 | Using index | 
| 1 | SIMPLE | p | eq_ref | PRIMARY,links | PRIMARY | 4 | peekyou.pt.profile_id | 1 | 100.00 | Using where | 
| 1 | SIMPLE | pp | ref | prof_type | prof_type | 4 | peekyou.pt.profile_id | 1 | 100.00 | Using index | 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 

Execution: 40 rows in set (2.58 sec) 

More info on the hardware:
Mysql 5.5.8 is running on 2 XEON six-core Intels + 24GB of ram + 2TB of SSD 
Mysql 5.1 is running on 1 XEON quad-core Intel + 16GB of ram + RAID10 15k RPM HDs

How to repeat:
Try re running identical query

Suggested fix:
According to Explain output:

That 3rd step could be done two ways -- grab all the phone numbers then do LIMIT 40. Or it could walk through, checking each person for having a phone, and stopping at 40. The first way would involve millions of probes, the second would involve 40 (or a few more). I wonder if one version is realizes that there is no further filtering going on, and does the LIMIT first, thereby eliminating millions of lookups in profile_phones.
[4 Feb 2011 16:46] Valeriy Kravchuk
Looks like you pasted output from 5.5.8 two times, so 5.1 results are missing.
[4 Feb 2011 16:47] Valeriy Kravchuk
Also, please, send CREATE TABLE statements for all tables involved. What exact 5.1.x version are you comparing to?
[4 Feb 2011 16:55] Pavel Baranov
Opps,

Comparing to mysql 5.1.46

ON 5.1 : 
mysql> explain extended select STRAIGHT_JOIN p.id from profile_thumbs_name as pt join profiles as p on p.id = pt.profile_id join profile_phones as pp on pp.profile_id = p.id where p.links > -1 order by pt.profile_id desc limit 40; 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra | 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 
| 1 | SIMPLE | pt | index | PRIMARY,profile_thumb | PRIMARY | 4 | NULL | 40 | 53541636.00 | Using index | 
| 1 | SIMPLE | p | eq_ref | PRIMARY,links | PRIMARY | 4 | peekyou.pt.profile_id | 1 | 100.00 | Using where | 
| 1 | SIMPLE | pp | ref | prof_type | prof_type | 4 | peekyou.pt.profile_id | 1 | 100.00 | Using index | 
+----+-------------+-------+--------+-----------------------+-----------+---------+-----------------------+------+-------------+-------------+ 

40 rows in set (0.20 sec) 

Creates:
mysql> SHOW CREATE TABLE profile_thumbs_name \G
*************************** 1. row ***************************
       Table: profile_thumbs_name
Create Table: CREATE TABLE `profile_thumbs_name` (
  `profile_id` int(11) NOT NULL,
  `thumbnail` varchar(100) COLLATE utf8_unicode_ci DEFAULT NULL,
  PRIMARY KEY (`profile_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci

mysql> SHOW CREATE TABLE profiles \G
*************************** 1. row ***************************
       Table: profiles
Create Table: CREATE TABLE `profiles` (
  `id` int(10) NOT NULL AUTO_INCREMENT,
  `created` datetime DEFAULT NULL,
  `status` tinyint(1) DEFAULT NULL,
  `active` tinyint(1) DEFAULT NULL,
  `locked` tinyint(1) DEFAULT NULL,
  `links` int(11) DEFAULT '0',
  `age` int(3) DEFAULT '0',
  `bday` date DEFAULT '0000-00-00',
  `sex` char(1) DEFAULT NULL,
  `first_name` int(8) DEFAULT NULL,
  `last_name` int(8) DEFAULT NULL,
  `middle_name` int(8) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `active` (`active`),
  KEY `createdi` (`created`),
  KEY `links` (`links`),
  KEY `age` (`age`),
  KEY `bday` (`bday`),
  KEY `first_links_sex_age_id` (`first_name`,`links`,`sex`,`age`,`id`),
  KEY `first_last_middle_links_sex_age_id` (`first_name`,`last_name`,`middle_name`,`links`,`sex`,`age`,`id`),
  KEY `last_links_sex_age_id` (`last_name`,`links`,`sex`,`age`,`id`),
  KEY `sex_age_links_id` (`sex`,`age`,`links`,`id`)
) ENGINE=InnoDB AUTO_INCREMENT=322334237 DEFAULT CHARSET=utf8

mysql> SHOW CREATE TABLE profile_phones \G
*************************** 1. row ***************************
       Table: profile_phones
Create Table: CREATE TABLE `profile_phones` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `profile_id` int(10) NOT NULL DEFAULT '0',
  `phone` varchar(14) DEFAULT NULL,
  `type` tinyint(4) NOT NULL DEFAULT '1',
  `created` date DEFAULT NULL,
  `status` int(1) DEFAULT '1',
  PRIMARY KEY (`id`),
  KEY `phone` (`phone`),
  KEY `prof_type` (`profile_id`,`type`)
) ENGINE=InnoDB AUTO_INCREMENT=111200000 DEFAULT CHARSET=latin1
[5 Feb 2011 19:59] Valeriy Kravchuk
On both 5.5.8 and 5.1.x, please, execute the following sequence of statements:

flush status;
SELECT ...
show status like 'Handler_read%';

and send the output of SHOW STATUS. This way we will see if there is any difference. Plans in EXPLAIN results look exactly the same (if I don't miss anything).
[7 Feb 2011 19:12] Pavel Baranov
I apologize but I would have to reload those two tables into 5.1 version since we completely switched to 5.5.8 and couldn't leave 5.1 operational due to replication.

I will eventually load it but it will take some time since those tables are like 80GB in size.

Is there any other way to check if there is a problem with query optimizer besides that ? (probably not, but I still have to ask ;)
[8 Feb 2011 8:05] Valeriy Kravchuk
Please, do this on 5.5.8 then:

flush status;
SELECT ...
show status like 'Handler_read%';

I want to know how data are really accessed there.
[21 Feb 2011 16:01] Pavel Baranov
mysql> show status like 'Handler_read%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Handler_read_first    | 0     |
| Handler_read_key      | 32177 |
| Handler_read_last     | 1     |
| Handler_read_next     | 39    |
| Handler_read_prev     | 16086 |
| Handler_read_rnd      | 0     |
| Handler_read_rnd_next | 0     |
+-----------------------+-------+
7 rows in set (0.00 sec)
[3 Mar 2011 17:22] Sveta Smirnova
Thank you for the report.

Is it possible to send us dump of all involved tables?
[3 Mar 2011 21:30] Pavel Baranov
I don't think i can do that - the info is very private, plus there are about 100+ million rows in those tables.

Should I send like a sample instead ? Not sure if that will help...
[5 Mar 2011 11:40] Sveta Smirnova
Pavel,

thank you for the update. Will additionally try with generic data first.
[16 Mar 2011 20:20] Sveta Smirnova
Finally verified as described.

SHOW PROFILE for mysql-trunk:

mysql> show profile;
+--------------------------------+-----------+
| Status                         | Duration  |
+--------------------------------+-----------+
| starting                       |  0.000052 |
| Waiting for query cache lock   |  0.000006 |
| checking query cache for query |  0.000161 |
| checking permissions           |  0.000009 |
| checking permissions           |  0.000004 |
| checking permissions           |  0.000011 |
| Opening tables                 |  0.001339 |
| System lock                    |  0.000033 |
| Waiting for query cache lock   |  0.000066 |
| init                           |  0.000066 |
| optimizing                     |  0.000050 |
| statistics                     |  0.027392 |
| preparing                      |  0.000072 |
| executing                      |  0.000006 |
| Sorting result                 |  0.000013 |
| Sending data                   | 79.427377 |
| end                            |  0.000017 |
| query end                      |  0.000010 |
| closing tables                 |  0.000036 |
| freeing items                  |  0.000036 |
| Waiting for query cache lock   |  0.000004 |
| freeing items                  |  0.000036 |
| Waiting for query cache lock   |  0.000003 |
| freeing items                  |  0.000003 |
| storing result in query cache  |  0.000008 |
| logging slow query             |  0.000004 |
| cleaning up                    |  0.000006 |
+--------------------------------+-----------+
27 rows in set (0.00 sec)

For 5.1:

mysql> show profile;
+--------------------------------+-----------+
| Status                         | Duration  |
+--------------------------------+-----------+
| starting                       |  0.000116 |
| checking query cache for query |  0.000200 |
| Opening tables                 |  0.000163 |
| System lock                    |  0.000030 |
| Table lock                     |  0.000088 |
| init                           |  0.000086 |
| optimizing                     |  0.000091 |
| statistics                     |  0.005875 |
| preparing                      |  0.000131 |
| executing                      |  0.000025 |
| Sorting result                 |  0.000034 |
| Sending data                   | 27.173200 |
| end                            |  0.000032 |
| query end                      |  0.000018 |
| freeing items                  |  0.000076 |
| storing result in query cache  |  0.000030 |
| logging slow query             |  0.000018 |
| logging slow query             |  0.000018 |
| cleaning up                    |  0.000047 |
+--------------------------------+-----------+
19 rows in set (0.00 sec)
[17 Mar 2011 14:08] Pavel Baranov
Thank you Svetlana for your time!

What would be the next step here?
[8 Feb 2012 16:37] Pavel Baranov
Was this fixed in any of the latest releases ?
[7 Mar 2012 0:14] Sveta Smirnova
Pavel,

we just tested my test case for this bug with current versions and could not repeat it anymore. Could you please confirm if it is fixed on your side too?

Thanks in advance.
[7 Mar 2012 0:14] Sveta Smirnova
Lowest version of 5.5 we used for testing is 5.5.21
[7 Apr 2012 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".