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: | |
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
[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".