| Bug #66849 | [REGRESSION] this query hangs the server (100% CPU for several minutes) | ||
|---|---|---|---|
| Submitted: | 17 Sep 2012 18:49 | Modified: | 10 Jun 2013 19:49 |
| Reporter: | matteo sisti sette | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Optimizer | Severity: | S1 (Critical) |
| Version: | 5.5.16, 5.1.70, 5.5.32, 5.6.12 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
[17 Sep 2012 18:49]
matteo sisti sette
[17 Sep 2012 19:50]
MySQL Verification Team
Please try version 5.5.27. If the issue is still present provide a complete test case. Thanks.
[17 Sep 2012 21:49]
matteo sisti sette
I have just tested 5.5.27 and the issue persists.
[17 Sep 2012 22:11]
matteo sisti sette
A very funny thing is that, if in the same query I replace "SELECT COUNT (DISTINCT t.id)" with "SELECT *", I get the response (about 15k rows) in a fraction of a second. So the issue seems to be with COUNT(DISTINCT)
[17 Sep 2012 22:55]
matteo sisti sette
Here's another query that used to perform well on 5.0.77 and now (on a copy of the same database) takes 1 minute: SELECT `t`.`id` AS `t0_c0`, `t`.`name` AS `t0_c1`, `t`.`visible` AS `t0_c2`, `t`.`description` AS `t0_c3`, `t`.`created_date` AS `t0_c4`, `t`.`created_user_id` AS `t0_c5`, `t`.`created_area_id` AS `t0_c6`, `t`.`created_device_id` AS `t0_c7`, IF (featured.area_id IS NOT NULL, 1, 0) AS is_featured, COUNT(messages.id) AS timesUsed, `translation1`.`id` AS `t1_c0`, `translation1`.`tag_id` AS `t1_c1`, `translation1`.`language_id` AS `t1_c2`, `translation1`.`value` AS `t1_c3`, `translation1`.`visible` AS `t1_c4`, `translation2`.`id` AS `t2_c0`, `translation2`.`tag_id` AS `t2_c1`, `translation2`.`language_id` AS `t2_c2`, `translation2`.`value` AS `t2_c3`, `translation2`.`visible` AS `t2_c4`, `translation3`.`id` AS `t3_c0`, `translation3`.`tag_id` AS `t3_c1`, `translation3`.`language_id` AS `t3_c2`, `translation3`.`value` AS `t3_c3`, `translation3`.`visible` AS `t3_c4`, `translation4`.`id` AS `t4_c0`, `translation4`.`tag_id` AS `t4_c1`, `translation4`.`language_id` AS `t4_c2`, `translation4`.`value` AS `t4_c3`, `translation4`.`visible` AS `t4_c4`, `translation5`.`id` AS `t5_c0`, `translation5`.`tag_id` AS `t5_c1`, `translation5`.`language_id` AS `t5_c2`, `translation5`.`value` AS `t5_c3`, `translation5`.`visible` AS `t5_c4`, `translation6`.`id` AS `t6_c0`, `translation6`.`tag_id` AS `t6_c1`, `translation6`.`language_id` AS `t6_c2`, `translation6`.`value` AS `t6_c3`, `translation6`.`visible` AS `t6_c4`, `translation7`.`id` AS `t7_c0`, `translation7`.`tag_id` AS `t7_c1`, `translation7`.`language_id` AS `t7_c2`, `translation7`.`value` AS `t7_c3`, `translation7`.`visible` AS `t7_c4`, `translation8`.`id` AS `t8_c0`, `translation8`.`tag_id` AS `t8_c1`, `translation8`.`language_id` AS `t8_c2`, `translation8`.`value` AS `t8_c3`, `translation8`.`visible` AS `t8_c4` FROM `tag` `t` LEFT JOIN tag_featured_area AS featured ON featured.tag_id=t.id AND featured.area_id=13 LEFT JOIN (tag_x_message AS xmessages LEFT JOIN message AS messages ON xmessages.message_id=messages.id ) ON xmessages.tag_id=t.id AND messages.area_id=13 LEFT OUTER JOIN `tag_translation` `translation1` ON (`translation1`.`tag_id`=`t`.`id`) AND (translation1.language_id=1) LEFT OUTER JOIN `tag_translation` `translation2` ON (`translation2`.`tag_id`=`t`.`id`) AND (translation2.language_id=2) LEFT OUTER JOIN `tag_translation` `translation3` ON (`translation3`.`tag_id`=`t`.`id`) AND (translation3.language_id=3) LEFT OUTER JOIN `tag_translation` `translation4` ON (`translation4`.`tag_id`=`t`.`id`) AND (translation4.language_id=4) LEFT OUTER JOIN `tag_translation` `translation5` ON (`translation5`.`tag_id`=`t`.`id`) AND (translation5.language_id=5) LEFT OUTER JOIN `tag_translation` `translation6` ON (`translation6`.`tag_id`=`t`.`id`) AND (translation6.language_id=6) LEFT OUTER JOIN `tag_translation` `translation7` ON (`translation7`.`tag_id`=`t`.`id`) AND (translation7.language_id=7) LEFT OUTER JOIN `tag_translation` `translation8` ON (`translation8`.`tag_id`=`t`.`id`) AND (translation8.language_id=8) GROUP BY t.id ORDER BY IF (t.visible AND (COUNT(messages.id)>0 OR featured.area_id IS NOT NULL OR t.created_area_id=13 ), 0, 1), timesUsed DESC LIMIT 50
[18 Sep 2012 13:14]
matteo sisti sette
Finally I have been able to test an older version (namely 5.0.37) on the same machine where the latest version was performing badly, and it exhibits the same issue, so it must be a problem in my configuration and not a bug in MySQL.
[9 Oct 2012 11:05]
matteo sisti sette
I've observed this again, and with several different queries (all a bit complex and with multiple JOINs) and I've found out the following: - it is not a matter of MySQL version, I have observed it on both 5.0.77 and 5.5.16 - it is not a matter of server configuration, or at least, I have observed it on both (a) my local machine which has xampp with MySQL 5.5.16 with the settings that are shipped by default by xampp, and (b) on an online server which has CentOS 5.5 and MySQL 5.0.77 with ALL MYSQL's DEFAULT settings (i.e. nothing in my.cnf). - it is kind of random: sometimes, after restarting the MySQL server, the same (exact) query on the same data stops being slow; sometimes it doesn't (i.e. it keeps being slow). When it does stop being slow, it then starts being slow again after some time the server is running. - some queries seem to hang systematically with some given values of a given parameter. For example this one: SELECT `t`.`id` AS `t0_c0`, `t`.`name` AS `t0_c1`, `t`.`long` AS `t0_c2`, `t`.`oldname` AS `t0_c3`, `translation1`.`iftext_id` AS `t1_c0`, `translation1`.`language_id` AS `t1_c1`, `translation1`.`value` AS `t1_c2`, `translation2`.`iftext_id` AS `t2_c0`, `translation2`.`language_id` AS `t2_c1`, `translation2`.`value` AS `t2_c2`, `translation3`.`iftext_id` AS `t3_c0`, `translation3`.`language_id` AS `t3_c1`, `translation3`.`value` AS `t3_c2`, `translation4`.`iftext_id` AS `t4_c0`, `translation4`.`language_id` AS `t4_c1`, `translation4`.`value` AS `t4_c2`, `translation5`.`iftext_id` AS `t5_c0`, `translation5`.`language_id` AS `t5_c1`, `translation5`.`value` AS `t5_c2`, `translation6`.`iftext_id` AS `t6_c0`, `translation6`.`language_id` AS `t6_c1`, `translation6`.`value` AS `t6_c2`, `translation7`.`iftext_id` AS `t7_c0`, `translation7`.`language_id` AS `t7_c1`, `translation7`.`value` AS `t7_c2`, `translation8`.`iftext_id` AS `t8_c0`, `translation8`.`language_id` AS `t8_c1`, `translation8`.`value` AS `t8_c2` FROM `iftext` `t` LEFT OUTER JOIN `iftext_translation_language` `translation1` ON (`translation1`.`iftext_id`=`t`.`id`) AND (translation1.language_id=1) LEFT OUTER JOIN `iftext_translation_language` `translation2` ON (`translation2`.`iftext_id`=`t`.`id`) AND (translation2.language_id=2) LEFT OUTER JOIN `iftext_translation_language` `translation3` ON (`translation3`.`iftext_id`=`t`.`id`) AND (translation3.language_id=3) LEFT OUTER JOIN `iftext_translation_language` `translation4` ON (`translation4`.`iftext_id`=`t`.`id`) AND (translation4.language_id=4) LEFT OUTER JOIN `iftext_translation_language` `translation5` ON (`translation5`.`iftext_id`=`t`.`id`) AND (translation5.language_id=5) LEFT OUTER JOIN `iftext_translation_language` `translation6` ON (`translation6`.`iftext_id`=`t`.`id`) AND (translation6.language_id=6) LEFT OUTER JOIN `iftext_translation_language` `translation7` ON (`translation7`.`iftext_id`=`t`.`id`) AND (translation7.language_id=7) LEFT OUTER JOIN `iftext_translation_language` `translation8` ON (`translation8`.`iftext_id`=`t`.`id`) AND (translation8.language_id=8) WHERE (`t`.`name`=:yp0) When :yp0 is bound to 'user.login.password' it takes between 7 and 30 seconds (!!!!) to complete. When :yp0 in the same query is bound to some other value, it takes just a couple of milliseconds. (iftext.name, language.id, iftext_translation_language.language_id and iftext_translation_language.iftext_id are all indices) - May it be realted to parameter binding?? When I execute the same query above in phpMyAdmin and manually put the value "user.login.password" instead of :yp0, then it returns instantly!!!!!
[9 Oct 2012 11:07]
matteo sisti sette
when I said 5.5.16, it's 5.5.27 (I had also tested it on 5.5.16)
[9 Oct 2012 11:08]
matteo sisti sette
Ah I also did an OPTIMIZE TABLE on the three tables, and it didn't change a thing (actually I wonder whether it did anything at all, as it returned instantly)
[28 Oct 2012 19:09]
matteo sisti sette
Here we are again. A query that used to perform fine, now RANDOMLY starts to take ages (about 1 minute) while the data in the database hasn't changed significantly: Querying SQL: SELECT `t`.`id` AS `t0_c0`, `t`.`name` AS `t0_c1`, `t`.`visible` AS `t0_c2`, `t`.`description` AS `t0_c3`, `t`.`created_date` AS `t0_c4`, `t`.`created_user_id` AS `t0_c5`, `t`.`created_area_id` AS `t0_c6`, `t`.`created_device_id` AS `t0_c7`, IF (featured.area_id IS NOT NULL, 1, 0) AS is_featured, COUNT(messages.id) AS timesUsed, `translation1`.`id` AS `t1_c0`, `translation1`.`tag_id` AS `t1_c1`, `translation1`.`language_id` AS `t1_c2`, `translation1`.`value` AS `t1_c3`, `translation1`.`visible` AS `t1_c4`, `translation2`.`id` AS `t2_c0`, `translation2`.`tag_id` AS `t2_c1`, `translation2`.`language_id` AS `t2_c2`, `translation2`.`value` AS `t2_c3`, `translation2`.`visible` AS `t2_c4`, `translation3`.`id` AS `t3_c0`, `translation3`.`tag_id` AS `t3_c1`, `translation3`.`language_id` AS `t3_c2`, `translation3`.`value` AS `t3_c3`, `translation3`.`visible` AS `t3_c4`, `translation4`.`id` AS `t4_c0`, `translation4`.`tag_id` AS `t4_c1`, `translation4`.`language_id` AS `t4_c2`, `translation4`.`value` AS `t4_c3`, `translation4`.`visible` AS `t4_c4`, `translation5`.`id` AS `t5_c0`, `translation5`.`tag_id` AS `t5_c1`, `translation5`.`language_id` AS `t5_c2`, `translation5`.`value` AS `t5_c3`, `translation5`.`visible` AS `t5_c4`, `translation6`.`id` AS `t6_c0`, `translation6`.`tag_id` AS `t6_c1`, `translation6`.`language_id` AS `t6_c2`, `translation6`.`value` AS `t6_c3`, `translation6`.`visible` AS `t6_c4`, `translation7`.`id` AS `t7_c0`, `translation7`.`tag_id` AS `t7_c1`, `translation7`.`language_id` AS `t7_c2`, `translation7`.`value` AS `t7_c3`, `translation7`.`visible` AS `t7_c4`, `translation8`.`id` AS `t8_c0`, `translation8`.`tag_id` AS `t8_c1`, `translation8`.`language_id` AS `t8_c2`, `translation8`.`value` AS `t8_c3`, `translation8`.`visible` AS `t8_c4` FROM `tag` `t` LEFT JOIN tag_featured_area AS featured ON featured.tag_id=t.id AND featured.area_id=:areaId LEFT JOIN (tag_x_message AS xmessages LEFT JOIN message AS messages ON xmessages.message_id=messages.id ) ON xmessages.tag_id=t.id AND messages.area_id=:areaId LEFT OUTER JOIN `tag_translation` `translation1` ON (`translation1`.`tag_id`=`t`.`id`) AND (translation1.language_id=1) LEFT OUTER JOIN `tag_translation` `translation2` ON (`translation2`.`tag_id`=`t`.`id`) AND (translation2.language_id=2) LEFT OUTER JOIN `tag_translation` `translation3` ON (`translation3`.`tag_id`=`t`.`id`) AND (translation3.language_id=3) LEFT OUTER JOIN `tag_translation` `translation4` ON (`translation4`.`tag_id`=`t`.`id`) AND (translation4.language_id=4) LEFT OUTER JOIN `tag_translation` `translation5` ON (`translation5`.`tag_id`=`t`.`id`) AND (translation5.language_id=5) LEFT OUTER JOIN `tag_translation` `translation6` ON (`translation6`.`tag_id`=`t`.`id`) AND (translation6.language_id=6) LEFT OUTER JOIN `tag_translation` `translation7` ON (`translation7`.`tag_id`=`t`.`id`) AND (translation7.language_id=7) LEFT OUTER JOIN `tag_translation` `translation8` ON (`translation8`.`tag_id`=`t`.`id`) AND (translation8.language_id=8) GROUP BY t.id ORDER BY IF (t.visible AND (COUNT(messages.id)>0 OR featured.area_id IS NOT NULL OR t.created_area_id=:areaId ), 0, 1), timesUsed DESC LIMIT 50. Bound with :areaId='3' Ok, this is not an especially simple query, but if sometimes it takes a few milliseconds and other times, randomly, it takes more than one minute, then there is something seriously wrong. This is mysql server 5.5.27 The 'tag' table has only just a couple thousand records, and tag_translation has at most one record per tag per language (8 languages), so this is ridiculously slow. Please let me know what I can do to isolate the issue. Restarting the server and deleting the logfiles sometimes randomly ends up fixing the issue for a while, until it appears again.
[28 Oct 2012 19:20]
matteo sisti sette
Btw please ignore the query example in my comment of [9 Oct 11:05] because that just wasn't happening (I was misreading my application's logs). What still holds true is: - I observed the issue with queries like the one in my last comment and in my original report - I have certainly observed it on 5.5.16 and 5.5.27, now I'm not so sure whether I observed it on older versions (because in that case maybe I was observing the false issue) - I'm seeing this on Ubuntu 12.04 (desktop), MySQL 5.5.27 (in Xampp), on my local computer and until now I've never ever really seen this on my online server which has a much older version of MySQL, but I don't know for sure why. (same data, of course)
[28 Oct 2012 20:55]
matteo sisti sette
Here's the result of show profile. All the time is being spent in "copying to tmp table". What does that mean?
[29 Oct 2012 0:23]
matteo sisti sette
Whops, I thought I had pasted the output from the SHOW PROFILE! Now I don't have it any more. Anyway, about 99% of the 38 seconds was spent in "copying to tmp table"
[18 Dec 2012 18:42]
Sveta Smirnova
Thank you for the feedback. Could you please send us dump of all involved tables?
[19 Jan 2013 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".
[5 Apr 2013 19:11]
matteo sisti sette
Well I can't post a full dump of my database. Is that a reason for closing the bug?
[5 Apr 2013 19:16]
matteo sisti sette
UPDATE: What still holds true is: - I observed the issue with queries like the one in my last comment and in my original report - I have certainly observed it on 5.5.16 and 5.5.27, AND 5.0.95 - I'm seeing this on Ubuntu 12.04 (desktop), MySQL 5.5.27 (in Xampp), on my local computer AND on a CentOS 5.9 server with MySQL 5.0.95 MOST IMPORTANTLY, the issue is basically that: - At random time, queries like the ones mentioned above take about 30-90 seconds where 99.9% of the time is spent in "copying to tmp table", AND during that time, mysqld consumes 100% CPU. The tmp table is definitely not being created on disk (i. a priori, because the conditions are not meant which cause a tmp table to be created on disk, and ii, a posteriori, because if it was I would get high disk I/O, not high CPU usage)
[12 Apr 2013 20:13]
Sveta Smirnova
Thank you for the feedback. Well, this looks more like performance tuning request. Please send us output of EXPLAIN EXTENDED of your query, so we can guess if it should copy to temporary tables. However, to prove this is a bug in MySQL code, we need repeatable test case, so we need database structure and, better, minimal dump, so we can repeat the problem on our site.
[30 Apr 2013 23:05]
matteo sisti sette
Oh sh**, why didn't the bugtracker notify me of the reply!!! It DOES have to copy to temporary table. What doesn't make sense under any circumstance is that copying to temporary table can randomly take a fraction of a second or two minutes (of 100% cpu), for the same query (and note I have no query cache enabled). When the query is fast, it still has the same items shown in profile, only that the "copying to tmp table" phase just takes a few milliseconds.
[30 Apr 2013 23:09]
matteo sisti sette
EXPLAIN EXTENDED SELECT `t`.`id` AS `t0_c0`, `t`.`name` AS `t0_c1`, `t`.`visible` AS `t0_c2`, `t`.`description` AS `t0_c3`, `t`.`created_date` AS `t0_c4`, `t`.`created_user_id` AS `t0_c5`, `t`.`created_area_id` AS `t0_c6`, `t`.`created_device_id` AS `t0_c7`, IF (featured.area_id IS NOT NULL, 1, 0) AS is_featured, COUNT(messages.id) AS timesUsed, `translation1`.`id` AS `t1_c0`, `translation1`.`tag_id` AS `t1_c1`, `translation1`.`language_id` AS `t1_c2`, `translation1`.`value` AS `t1_c3`, `translation1`.`visible` AS `t1_c4`, `translation2`.`id` AS `t2_c0`, `translation2`.`tag_id` AS `t2_c1`, `translation2`.`language_id` AS `t2_c2`, `translation2`.`value` AS `t2_c3`, `translation2`.`visible` AS `t2_c4`, `translation3`.`id` AS `t3_c0`, `translation3`.`tag_id` AS `t3_c1`, `translation3`.`language_id` AS `t3_c2`, `translation3`.`value` AS `t3_c3`, `translation3`.`visible` AS `t3_c4`, `translation4`.`id` AS `t4_c0`, `translation4`.`tag_id` AS `t4_c1`, `translation4`.`language_id` AS `t4_c2`, `translation4`.`value` AS `t4_c3`, `translation4`.`visible` AS `t4_c4`, `translation5`.`id` AS `t5_c0`, `translation5`.`tag_id` AS `t5_c1`, `translation5`.`language_id` AS `t5_c2`, `translation5`.`value` AS `t5_c3`, `translation5`.`visible` AS `t5_c4`, `translation6`.`id` AS `t6_c0`, `translation6`.`tag_id` AS `t6_c1`, `translation6`.`language_id` AS `t6_c2`, `translation6`.`value` AS `t6_c3`, `translation6`.`visible` AS `t6_c4`, `translation7`.`id` AS `t7_c0`, `translation7`.`tag_id` AS `t7_c1`, `translation7`.`language_id` AS `t7_c2`, `translation7`.`value` AS `t7_c3`, `translation7`.`visible` AS `t7_c4`, `translation8`.`id` AS `t8_c0`, `translation8`.`tag_id` AS `t8_c1`, `translation8`.`language_id` AS `t8_c2`, `translation8`.`value` AS `t8_c3`, `translation8`.`visible` AS `t8_c4` FROM `tag` `t` LEFT JOIN tag_featured_area AS featured ON featured.tag_id=t.id AND featured.area_id=3 LEFT JOIN (tag_x_message AS xmessages LEFT JOIN message AS messages ON xmessages.message_id=messages.id ) ON xmessages.tag_id=t.id AND messages.area_id=3 LEFT OUTER JOIN `tag_translation` `translation1` ON (`translation1`.`tag_id`=`t`.`id`) AND (translation1.language_id=1) LEFT OUTER JOIN `tag_translation` `translation2` ON (`translation2`.`tag_id`=`t`.`id`) AND (translation2.language_id=2) LEFT OUTER JOIN `tag_translation` `translation3` ON (`translation3`.`tag_id`=`t`.`id`) AND (translation3.language_id=3) LEFT OUTER JOIN `tag_translation` `translation4` ON (`translation4`.`tag_id`=`t`.`id`) AND (translation4.language_id=4) LEFT OUTER JOIN `tag_translation` `translation5` ON (`translation5`.`tag_id`=`t`.`id`) AND (translation5.language_id=5) LEFT OUTER JOIN `tag_translation` `translation6` ON (`translation6`.`tag_id`=`t`.`id`) AND (translation6.language_id=6) LEFT OUTER JOIN `tag_translation` `translation7` ON (`translation7`.`tag_id`=`t`.`id`) AND (translation7.language_id=7) LEFT OUTER JOIN `tag_translation` `translation8` ON (`translation8`.`tag_id`=`t`.`id`) AND (translation8.language_id=8) GROUP BY t.id ORDER BY IF (t.visible AND (COUNT(messages.id)>0 OR featured.area_id IS NOT NULL OR t.created_area_id=3 ), 0, 1), IF (featured.area_id IS NOT NULL, 0, 1), timesUsed DESC LIMIT 50; +----+-------------+--------------+--------+------------------------------------------------------+-----------------+---------+--------------------------------------------------+------+----------+---------------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+-------------+--------------+--------+------------------------------------------------------+-----------------+---------+--------------------------------------------------+------+----------+---------------------------------+ | 1 | SIMPLE | t | index | NULL | PRIMARY | 4 | NULL | 2068 | 100.00 | Using temporary; Using filesort | | 1 | SIMPLE | featured | eq_ref | PRIMARY,FK_tgfta_area | PRIMARY | 8 | megafone_access.t.id,const | 1 | 100.00 | Using index | | 1 | SIMPLE | messages | ref | PRIMARY,area_id | area_id | 4 | const | 10 | 100.01 | Using index | | 1 | SIMPLE | xmessages | eq_ref | PRIMARY,FK_tgxmsg_message | PRIMARY | 8 | megafone_access.t.id,megafone_access.messages.id | 1 | 100.00 | Using index | | 1 | SIMPLE | translation1 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation2 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation3 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation4 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation5 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation6 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation7 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | | 1 | SIMPLE | translation8 | eq_ref | tag_lang_unique,FK_tgtrans_language,FK_tgtrans_tagid | tag_lang_unique | 8 | megafone_access.t.id,const | 1 | 100.00 | | +----+-------------+--------------+--------+------------------------------------------------------+-----------------+---------+--------------------------------------------------+------+----------+---------------------------------+
[30 Apr 2013 23:13]
matteo sisti sette
If the time is being spent in something else that is intrinsically cpu-intensive, (e.g. count()ing or sorting), then what is broken is the profiling that says that all of the time is spent in "copying to tmp tables"; but also it doesn't make sense that it sometimes happens and sometimes not on the same query (without caching being enabled).
[30 Apr 2013 23:14]
matteo sisti sette
SHOW PROFILE FOR QUERY 1; +----------------------+-----------+ | Status | Duration | +----------------------+-----------+ | starting | 0.000471 | | checking permissions | 0.000009 | | checking permissions | 0.000005 | | checking permissions | 0.000005 | | checking permissions | 0.000005 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000005 | | checking permissions | 0.000005 | | checking permissions | 0.000005 | | checking permissions | 0.000004 | | checking permissions | 0.000005 | | checking permissions | 0.000008 | | Opening tables | 0.000077 | | System lock | 0.000023 | | init | 0.000143 | | optimizing | 0.000018 | | statistics | 0.000376 | | preparing | 0.000114 | | Creating tmp table | 0.000414 | | Sorting for group | 0.000012 | | executing | 0.000005 | | Copying to tmp table | 66.952434 | | Sorting result | 0.013579 | | Sending data | 0.000824 | | end | 0.000010 | | removing tmp table | 0.000109 | | end | 0.000008 | | query end | 0.000011 | | closing tables | 0.000034 | | freeing items | 0.001114 | | logging slow query | 0.000006 | | logging slow query | 0.000005 | | cleaning up | 0.000008 | +----------------------+-----------+
[30 Apr 2013 23:17]
matteo sisti sette
I could send you a dump privately, but actually I would have to remove sensitive information like addresses, names, phone numbers (the table that contains it is not relevant to this query but I'm afraid I can't just remove it, without breaking some constraints)
[6 May 2013 19:13]
Sveta Smirnova
Thank you for the feedback. You should receive email notification. Please check your Junk filters. > I could send you a dump privately, but actually I would have to remove sensitive information like addresses, names, phone numbers (the table that contains it is not relevant to this query but I'm afraid I can't just remove it, without breaking some constraints) Please send. At least send output of mysqldump --no-data for all involved tables: probably I could repeat it with dummy data. However having the fact query runs slow sporadically I think external factors can affect this. Please run queries SHOW FULL PROCESSLIST and SHOW ENGINE INNODB STATUS in parallel connection in time when query is slow.
[17 May 2013 17:33]
matteo sisti sette
Please give me an email address where I can send a database dump. I have a dump with the personal information of users stripped out, however I don't feel like sharing the whole database publicly. Also it's about 15Mb and I guess I won't be able to upload it here. >Please run queries SHOW FULL PROCESSLIST and SHOW ENGINE INNODB STATUS in parallel connection in time when query is slow. Could you please give me more detailed instructions about this? Note that whatever external factors may be influencing this, there is _certainly_ something buggy, as: - the query doesn't meet the criteria such that the tmp table should be created on disk, so it must be certainly created in memory - it can't be there's not enough memory, as even the whole database is just 15MB (as a rule of thumb the tmp table for this query can't be much more than that). - Not even DOWNLOADING a dump of the whole database takes as long as running that query, so even if for some wicked reason the tmp table was being created on disk, it can't take that long to just copy the data - it consumes 100% cpu while doing the query, so it's not disk I/O (or something is very broken if disk I/O takes 100% CPU) - if it's the sorting that is taking long, or anything else other than the mere copying to temporary table, then it's the PROFILER that is broken, because it says all the time is being spent in "copying to tmp table". - remember it's random, not systematic, even with no cache enabled (that I know of); and even when the query runs fast, the steps shown by the profiler are the same
[27 May 2013 19:26]
matteo sisti sette
So please where can I send the database dump, so that maybe this gets fixed before 2020?
[10 Jun 2013 16:30]
Sveta Smirnova
Thank you for the feedback. Please use instructions, located in "Files" tab of this bug report: http://bugs.mysql.com/bug.php?id=66849&files=1
[10 Jun 2013 16:41]
matteo sisti sette
Whops, I hadn't realised there is a privacy option for attached files :$
[10 Jun 2013 16:45]
matteo sisti sette
Attached it only visible to developers
[10 Jun 2013 18:01]
Sveta Smirnova
Thank you for the feedback. I could repeat slowdown in version 5.1 and 5.5, but 5.6 is similar to 5.0, although slightly slower. Timing for the query: 5.0: 1 sec 5.1: 2 min 3 sec 5.5: 5 min 10 sec 5.6: 5 sec I believe this happens, because query optimizer was rewritten and in version 5.6 is much better than in version 5.5 and 5.1. But, at the same time, other factors, as the fact than MySQL server is more complicated now, can slightly affect query resolution time. Please inform us if this is OK to close this bug as fixed in version 5.6 or you still want it to be open having this slight difference. In versions 5.1 and 5.5 you can set option optimizer_prune_level to 63: this will tell optimizer to mimic 5.0 behavior.
[10 Jun 2013 19:13]
matteo sisti sette
Note that I observed the issue also on 5.0.77. Are you sure it depends on the version? Because at first when I observed it happening on a server and not on another I thought it was the version, but then I observed the opposite situatuon, and found out it happens at random times on both versions I tested. It has never been systematic. (still have to try 5.6, though) Have you tested several times per version? Also, 5 secs vs 1 sec is kind of a regression even compared to version 5.0...
[10 Jun 2013 19:15]
matteo sisti sette
In my previous comment, replace whatever 5.0.x I said with 5.0.95
[10 Jun 2013 19:49]
Sveta Smirnova
Thank you for the feedback. I tested with current development sources, so this is strange you have slower results in 5.0.95 Anyway, this slight regression is verified. Regarding to workaround. At first, I mixed name of the variable. Then I tested optimizer-search-depth=63 and it did not help. So there is no workaround.
