| Bug #103256 | Randomly fails to pick obvious index (primary key) for left join | ||
|---|---|---|---|
| Submitted: | 8 Apr 2021 17:41 | Modified: | 13 Apr 2021 17:51 |
| Reporter: | teo teo | Email Updates: | |
| Status: | Can't repeat | Impact on me: | |
| Category: | MySQL Server | Severity: | S3 (Non-critical) |
| Version: | 5.7.26 | OS: | Debian |
| Assigned to: | CPU Architecture: | Any | |
[8 Apr 2021 19:46]
Øystein Grøvlen
It seems the optimizer thinks there is only 1 row in the avatar table. I suggest you try to run ANALYZE TABLE to see if that fixes the statistics.
[9 Apr 2021 11:40]
teo teo
> It seems the optimizer thinks there is only 1 row in the avatar table Actually, the table is empty. Which is not a reason for the query becoming 100 times slower.
[9 Apr 2021 13:26]
MySQL Verification Team
Hi Mr. teo, Thank you for your bug report. However, we can not proceed without a proper test case. You do not have to send all rows, but only the sufficient number which would make our Optimiser to pick a wrong index. Last, but not least, please first test your query with our last 5.7 release, which is 5.7.34.
[9 Apr 2021 14:23]
teo teo
> You do not have to send all rows, but only the sufficient number which would make our Optimiser to pick a wrong index.
Yeah but I have no idea how many that is. Our application has been running with that query virtually unchanged for literally more than a decade without ever exhibiting the issue until recently; plus actually this is a test replica of the live database, and the issue only happen on the test one, while there's no known difference between the two (on the same machine) except for the random live data that has been added to the live database since the test copy was made. The main table ('post') involved in the query has more than 2 million rows.
> we can not proceed without a proper test case
Life isn't always that easy. I wish I were always given a test case (let alone "proper") whenever a bug is found in my code or code I maintain.
> Last, but not least, please first test your query with our last
> 5.7 release, which is 5.7.34.
That I guess I can try.
[9 Apr 2021 15:10]
MySQL Verification Team
Sorry, but in order to verify this report, we need a proper test case.
[9 Apr 2021 15:20]
teo teo
Well then either you start working on figuring out how to create one with the information you have, or you do nothing and wait until someone else is hit by the bug again a few years from now and happens to be able to provide more information. I did my part. By the way, I found a report from 2013 that seems to describe the same issue: https://bugs.mysql.com/bug.php?id=69721&thanks=3¬ify=199 In 2020 someone said it to be a "documentation" issue and that it's fixed in documentation, without providing any explanation or link. Any chance you can clarify that?
[11 Apr 2021 18:38]
Øystein Grøvlen
If the table is empty, there is really no need to use an index. Are you sure there are no other differences in the query plan when the query is slow?
[11 Apr 2021 21:43]
teo teo
Difference between what and what? What I know is: - on that particular database (which I'll call database B), the query without "FORCE INDEX" is slow. With "FORCE INDEX" it becomes fast. - it also becomes fast if I remove the LEFT JOIN for table 'avatar' - it also becomes fast if I leave the LEFT JOIN avatar as in the original query, but I remove all the fields from that table from SELECT (I guess the optimizer is smart enough to see that I'm joining a table that I'm not using for anything at all and so it drops the join entirely - that's the only explanation I can think of) - the EXPLAIN without "force index" was as shown. With "FORCE INDEX" the line about the avatar table becomes: 1 | PRIMARY | avatar | NULL | eq_ref | PRIMARY | PRIMARY | 2 | ***.user.avatarid | 1 | 100.00 | Using where - On the very same database, where nothing in structure has changed (just some data has been added by using the website), the same query had never been slow until very recently - this database B is a snapshot of a database A taken from a live website some time ago. On the live website the exact same query is not and never has been slow. The reason I assumed the issue has to do with a wrong index being picked for that particular table, is that: - first thing I did after detecting the slow query was look at the EXPLAIN and the lack of an index and the "using ...." were the only things that looked strange - as mentioned above, adding FORCE INDEX or removing the join makes the query fast. Now I see that, if the table is empty, then even failing to use the proper index should make no difference, right? Even doing that particular join in the worst, wrongest imaginable way, couldn't possibly slow down the query, right? So, the logical conclusion should be that the lack of an index in the EXPLAIN (and the "using ...") is not an issue and that it doesn't explain the query being slow. But then again, the query does become fast when adding FORCE INDEX and also when removing that particular join. PERHAPS the bug causing the ridiculously slow query has nothing to do with that join, and it's not visible in the EXPLAIN (I can't see anything else wrong in the explain), and it's just randomly triggered by not using the index and by having that join, just like it's randomly triggered by some other random small differences in data (not structure) between two databases and between different moments in time in the same database when it randomly started being slow recently...?
[12 Apr 2021 13:28]
teo teo
So I remembered about profiling. I ran: - SET SESSION profiling = 1; - then (after selecting the database) the query, which took 107 seconds - SHOW PROFILES output: | 1 | 0.00499325 | SELECT DATABASE() | | 2 | 107.70861800 | SELECT post.*, post.username ... (the slow query) and finally: - SHOW PROFILE FOR QUERY 2 but the output is obviously bull***t because none of the durations shown is more than a tiny fraction of a second: +-------------------------------+----------+ | Status | Duration | +-------------------------------+----------+ | executing | 0.000005 | | Sending data | 0.000043 | | executing | 0.000004 | | Sending data | 0.000002 | | Creating sort index | 0.004047 | | executing | 0.000005 | | Sending data | 0.000044 | | executing | 0.000004 | | Sending data | 0.000002 | | Creating sort index | 0.004136 | | executing | 0.000006 | | Sending data | 0.000044 | | executing | 0.000004 | | Sending data | 0.000002 | | Creating sort index | 0.010292 | | executing | 0.000021 | | Sending data | 0.000194 | | executing | 0.000009 | | Sending data | 0.000005 | | Creating sort index | 0.009286 | | executing | 0.000019 | | Sending data | 0.000149 | | executing | 0.000006 | | Sending data | 0.000003 | | Creating sort index | 0.008108 | | executing | 0.000018 | | Sending data | 0.000145 | | executing | 0.000007 | | Sending data | 0.000004 | | Creating sort index | 0.007995 | | executing | 0.000018 | | Sending data | 0.000150 | | executing | 0.000007 | | Sending data | 0.000004 | | Creating sort index | 0.008300 | | executing | 0.000015 | | Sending data | 0.000149 | | executing | 0.000006 | | Sending data | 0.000004 | | Creating sort index | 0.007787 | | executing | 0.000015 | | Sending data | 0.000155 | | executing | 0.000014 | | Sending data | 0.000004 | | Creating sort index | 0.007546 | | executing | 0.000016 | | Sending data | 0.000145 | | executing | 0.000007 | | Sending data | 0.000003 | | Creating sort index | 0.007265 | | executing | 0.000017 | | Sending data | 0.000147 | | executing | 0.000007 | | Sending data | 0.000004 | | Creating sort index | 0.007718 | | executing | 0.000017 | | Sending data | 0.000150 | | executing | 0.000007 | | Sending data | 0.000004 | | Creating sort index | 0.007204 | | executing | 0.000015 | | Sending data | 0.000104 | | executing | 0.000005 | | Sending data | 0.000003 | | Creating sort index | 0.004157 | | executing | 0.000011 | | Sending data | 0.000081 | | executing | 0.000005 | | Sending data | 0.000003 | | Creating sort index | 0.004125 | | executing | 0.000014 | | Sending data | 0.000092 | | executing | 0.000005 | | Sending data | 0.000003 | | Creating sort index | 0.004210 | | executing | 0.000011 | | Sending data | 0.000080 | | executing | 0.000005 | | Sending data | 0.000003 | | Creating sort index | 0.004043 | | executing | 0.000012 | | Sending data | 0.000081 | | executing | 0.000004 | | Sending data | 0.000003 | | Creating sort index | 0.004067 | | executing | 0.000011 | | Sending data | 0.000061 | | Creating sort index | 0.000624 | | end | 0.000007 | | query end | 0.000015 | | removing tmp table | 0.000043 | | query end | 0.000015 | | closing tables | 0.000092 | | freeing items | 0.000049 | | Waiting for query cache lock | 0.000004 | | freeing items | 0.000200 | | Waiting for query cache lock | 0.000005 | | freeing items | 0.000003 | | storing result in query cache | 0.000004 | | cleaning up | 0.000016 | +-------------------------------+----------+ Is profiling broken too or what am I missing?
[12 Apr 2021 13:58]
MySQL Verification Team
Start server without query cache and try again.
[12 Apr 2021 14:59]
teo teo
Removing the subquery for the `session` table also makes the query instant-fast. It looks like removing random parts of the query that don't seem to have any reason for being responsible for the performance issue, makes the performance issue go away. Query without the `session` subquery but with the `avatar` join: fast. Query without the `avatar` join but with the `session` subquery: fast. Query with both: slow. It's almost as if "too many" joins and subqueries were an issue.
[12 Apr 2021 15:28]
teo teo
Ok, my "experiments" with variants of the query being fast or slow were garbage because of caching. Starting the server without cache is not an option, because there are live applications using the same server. All I can do is add SQL_NO_CACHE to the query. However, see my comment from 12 Apr 13:28: I have replicated that with SQL_NO_CACHE and the result is the same. If the sum of the durations in SHOW PROFILE is not even close to the total duration of the query, something is wrong. What am I missing?
[12 Apr 2021 16:46]
teo teo
Ok, I have something interesting. First of all, below is a slightly updated testing query, with SQL_NO_CACHE and with only two IDs in the IN() condition (one being 0), so that it's still unacceptably slow but it takes around 10 seconds rather than a minute and a half. Here's a comparison of data in performance_schema in two cases: on the left the query done against the live database where it's fast as expected; on the right the same query done against the cloned database where it's ridiculously slow. Again, the structure of both databases is identical and the data very similar. In both, the `post` table contains millions of rows and the query returns one. As you can see, the "examined rows" in the failing case is an astonishing 5 millions, versus 35 in the sane case. I have no idea where that difference comes from, or from which table it's scanning such an insane amount of rows. https://editor.mergely.com/GMZ65zeR/ ============== test query ============ SELECT SQL_NO_CACHE post.*, post.username AS postusername, post.ipaddress AS ip, IF(post.visible = 2, 1, 0) AS isdeleted, user.*, userfield.*, usertextfield.*, icon.title as icontitle, icon.iconpath, avatar.avatarpath, NOT ISNULL(customavatar.userid) AS hascustomavatar, customavatar.dateline AS avatardateline,customavatar.width AS avwidth,customavatar.height AS avheight, spamlog.postid AS spamlog_postid, deletionlog.userid AS del_userid, deletionlog.username AS del_username, deletionlog.reason AS del_reason, editlog.userid AS edit_userid, editlog.username AS edit_username, editlog.dateline AS edit_dateline, editlog.reason AS edit_reason, editlog.hashistory, postparsed.pagetext_html, postparsed.hasimages, sigparsed.signatureparsed, sigparsed.hasimages AS sighasimages, sigpic.userid AS sigpic, sigpic.dateline AS sigpicdateline, sigpic.width AS sigpicwidth, sigpic.height AS sigpicheight, IF(displaygroupid=0, user.usergroupid, displaygroupid) AS displaygroupid, infractiongroupid , post_icon_list.icon_id_list, infractionlevel.icon_url AS infraction_icon_url, approvedlog.modid AS approvedmodid, approvedlog.dateline AS approveddateline, approvedlog.status AS approvedstatus, approvedlog.info AS approvedinfo, movedlog.modid AS movedmodid, movedlog.dateline AS moveddateline, movedlog.status AS movedstatus, movedlog.info AS movedinfo, infraction.infractionlevelid, ( SELECT useragent FROM session WHERE userid=post.userid AND lastactivity > 1617897512 ORDER BY lastactivity DESC LIMIT 1 ) AS useragent, IF ( user.userid IS NOT NULL, (SELECT COUNT(usernoteid) FROM usernote AS usernote WHERE usernote.userid=user.userid AND usernote.priority>=0), 0 ) AS usernotecount , scheduled_approval.defer_time AS vbpmal_approval_defer_time, additional_user_data.last_year_message_count, additional_user_data.last_year_reputation, additional_user_data.last_year_groan_count, paid_post_activation.activation_id AS paid_post_activation_id, alm_Model_UserData.credits FROM post AS post LEFT JOIN user AS user ON(user.userid = post.userid) LEFT JOIN userfield AS userfield ON(userfield.userid = user.userid) LEFT JOIN usertextfield AS usertextfield ON(usertextfield.userid = user.userid) LEFT JOIN icon AS icon ON(icon.iconid = post.iconid) LEFT JOIN avatar AS avatar ON(avatar.avatarid = user.avatarid) LEFT JOIN customavatar AS customavatar ON(customavatar.userid = user.userid) LEFT JOIN spamlog AS spamlog ON(spamlog.postid = post.postid) LEFT JOIN deletionlog AS deletionlog ON(post.postid = deletionlog.primaryid AND deletionlog.type = 'post') LEFT JOIN editlog AS editlog ON(editlog.postid = post.postid) LEFT JOIN postparsed AS postparsed ON(postparsed.postid = post.postid AND postparsed.styleid = 23 AND postparsed.languageid = 5) LEFT JOIN sigparsed AS sigparsed ON(sigparsed.userid = user.userid AND sigparsed.styleid = 23 AND sigparsed.languageid = 5) LEFT JOIN sigpic AS sigpic ON(sigpic.userid = post.userid) LEFT JOIN vbppim_post_icon_list AS post_icon_list ON post_icon_list.post_id=post.postid LEFT JOIN vbpmal_log AS approvedlog ON (approvedlog.itemid=post.postid AND approvedlog.action='postapprove') LEFT JOIN vbpmal_log AS movedlog ON (movedlog.itemid=post.postid AND movedlog.action='postmove') LEFT JOIN infraction AS infraction ON infraction.postid=post.postid LEFT JOIN session AS session ON (session.userid = user.userid) LEFT JOIN infractionlevel AS infractionlevel ON (infractionlevel.infractionlevelid = infraction.infractionlevelid) LEFT JOIN vbpmal_scheduled_post_approval AS scheduled_approval ON scheduled_approval.post_id = post.postid LEFT JOIN vbpsmt_additional_user_data AS additional_user_data ON additional_user_data.userid=post.userid LEFT JOIN market_pp_post_activation_mapping AS paid_post_activation ON paid_post_activation.post_id = post.postid LEFT JOIN alm_Model_UserData AS alm_Model_UserData ON alm_Model_UserData.user_id=user.userid WHERE post.postid IN (0,2986476) GROUP BY post.postid ORDER BY post.dateline
[13 Apr 2021 12:45]
MySQL Verification Team
Hi Mr. teo, For many good reasons, query cache is now obsolete and we can't accept bug reports that involve that feature.
[13 Apr 2021 17:51]
teo teo
The issue has nothing to do with query cache. The query cache was only interfering in trying to narrow down the issue. Anyway I found out that there *are* a few things that are wrong with my query *and* my data, though I'm still seeing inconsistencies in the server's behavior, but I need to check a few more things. However, your comment about cache makes me realize that you don't even read the information I give you, so I'm not sure I'll come back with more information as it seems to be a waste of time anyway.
Description: I know you want a reproducible test case with example data. I cannot provide that. I'll provide what I can. There is enough information to tell for sure that there's a bug. The query below has a few left joins with trivial ON conditions on a primary key of the joined table. In particular, this: LEFT JOIN avatar ON (avatar.avatarid=user.avatarid) where the table 'avatar' has a primary key on its column 'avatarid'. At random times, MySQL miserably fails to use such an obvious index for the join, causing the query to take hundreds of seconds instead of a fraction of a second. How to repeat: Here's the query: SELECT post.*, post.username AS postusername, post.ipaddress AS ip, IF(post.visible = 2, 1, 0) AS isdeleted, user.*, userfield.*, usertextfield.*, icon.title as icontitle, icon.iconpath, avatar.avatarpath, NOT ISNULL(customavatar.userid) AS hascustomavatar, customavatar.dateline AS avatardateline,customavatar.width AS avwidth,customavatar.height AS avheight, spamlog.postid AS spamlog_postid, deletionlog.userid AS del_userid, deletionlog.username AS del_username, deletionlog.reason AS del_reason, editlog.userid AS edit_userid, editlog.username AS edit_username, editlog.dateline AS edit_dateline, editlog.reason AS edit_reason, editlog.hashistory, postparsed.pagetext_html, postparsed.hasimages, sigparsed.signatureparsed, sigparsed.hasimages AS sighasimages, sigpic.userid AS sigpic, sigpic.dateline AS sigpicdateline, sigpic.width AS sigpicwidth, sigpic.height AS sigpicheight, IF(displaygroupid=0, user.usergroupid, displaygroupid) AS displaygroupid, infractiongroupid , post_icon_list.icon_id_list, infractionlevel.icon_url AS infraction_icon_url, approvedlog.modid AS approvedmodid, approvedlog.dateline AS approveddateline, approvedlog.status AS approvedstatus, approvedlog.info AS approvedinfo, movedlog.modid AS movedmodid, movedlog.dateline AS moveddateline, movedlog.status AS movedstatus, movedlog.info AS movedinfo, infraction.infractionlevelid, ( SELECT useragent FROM session WHERE userid=post.userid AND lastactivity > 1617897512 ORDER BY lastactivity DESC LIMIT 1 ) AS useragent, IF ( user.userid IS NOT NULL, (SELECT COUNT(usernoteid) FROM usernote AS usernote WHERE usernote.userid=user.userid AND usernote.priority>=0), 0 ) AS usernotecount , scheduled_approval.defer_time AS vbpmal_approval_defer_time, additional_user_data.last_year_message_count, additional_user_data.last_year_reputation, additional_user_data.last_year_groan_count, paid_post_activation.activation_id AS paid_post_activation_id, alm_Model_UserData.credits FROM post AS post LEFT JOIN user AS user ON(user.userid = post.userid) LEFT JOIN userfield AS userfield ON(userfield.userid = user.userid) LEFT JOIN usertextfield AS usertextfield ON(usertextfield.userid = user.userid) LEFT JOIN icon AS icon ON(icon.iconid = post.iconid) LEFT JOIN avatar AS avatar ON(avatar.avatarid = user.avatarid) LEFT JOIN customavatar AS customavatar ON(customavatar.userid = user.userid) LEFT JOIN spamlog AS spamlog ON(spamlog.postid = post.postid) LEFT JOIN deletionlog AS deletionlog ON(post.postid = deletionlog.primaryid AND deletionlog.type = 'post') LEFT JOIN editlog AS editlog ON(editlog.postid = post.postid) LEFT JOIN postparsed AS postparsed ON(postparsed.postid = post.postid AND postparsed.styleid = 23 AND postparsed.languageid = 5) LEFT JOIN sigparsed AS sigparsed ON(sigparsed.userid = user.userid AND sigparsed.styleid = 23 AND sigparsed.languageid = 5) LEFT JOIN sigpic AS sigpic ON(sigpic.userid = post.userid) LEFT JOIN vbppim_post_icon_list AS post_icon_list ON post_icon_list.post_id=post.postid LEFT JOIN vbpmal_log AS approvedlog ON (approvedlog.itemid=post.postid AND approvedlog.action='postapprove') LEFT JOIN vbpmal_log AS movedlog ON (movedlog.itemid=post.postid AND movedlog.action='postmove') LEFT JOIN infraction AS infraction ON infraction.postid=post.postid LEFT JOIN session AS session ON (session.userid = user.userid) LEFT JOIN infractionlevel AS infractionlevel ON (infractionlevel.infractionlevelid = infraction.infractionlevelid) LEFT JOIN vbpmal_scheduled_post_approval AS scheduled_approval ON scheduled_approval.post_id = post.postid LEFT JOIN vbpsmt_additional_user_data AS additional_user_data ON additional_user_data.userid=post.userid LEFT JOIN market_pp_post_activation_mapping AS paid_post_activation ON paid_post_activation.post_id = post.postid LEFT JOIN alm_Model_UserData AS alm_Model_UserData ON alm_Model_UserData.user_id=user.userid WHERE post.postid IN (0,2986476,2986477,2996106,3008369,3008367,3017504,3017569,3056537,3056542,3056543,3056544) GROUP BY post.postid ORDER BY post.dateline The table 'avatar' has a primary key on the column 'avatarid'. Here's the EXPLAIN for the query: +----+--------------------+----------------------+------------+--------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------+---------+-----------------------------------------+------+----------+----------------------------------------------------+ | id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+--------------------+----------------------+------------+--------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------+---------+-----------------------------------------+------+----------+----------------------------------------------------+ | 1 | PRIMARY | post | NULL | range | PRIMARY,userid,dateline,threadid_userid,threadid,reportthreadid,iconid,nominate_topic_amount,nominate_amount_per_contest,ipaddress,post_thanks_amount,vbpsmt_lastattachments_pending,vbmpw_phone_pending,vbmpw_hasphone_phonepending,vbmpw_is_ad,vbmpw_is_ad_valid_ad,threadid_dateline,vbmpw_last_scanned,vbmpw_last_scanned_etc,threadid_dateline_visible,title,vbmpw_partner_links | PRIMARY | 4 | NULL | 12 | 100.00 | Using where; Using temporary; Using filesort | | 1 | PRIMARY | user | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.userid | 1 | 100.00 | NULL | | 1 | PRIMARY | userfield | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.user.userid | 1 | 100.00 | NULL | | 1 | PRIMARY | usertextfield | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.user.userid | 1 | 100.00 | NULL | | 1 | PRIMARY | icon | NULL | eq_ref | PRIMARY | PRIMARY | 2 | clonedsql1.post.iconid | 1 | 100.00 | NULL | | 1 | PRIMARY | avatar | NULL | ALL | PRIMARY | NULL | NULL | NULL | 1 | 100.00 | Using where; Using join buffer (Block Nested Loop) | | 1 | PRIMARY | customavatar | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.user.userid | 1 | 100.00 | NULL | | 1 | PRIMARY | spamlog | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.postid | 1 | 100.00 | Using index | | 1 | PRIMARY | deletionlog | NULL | eq_ref | PRIMARY,type | PRIMARY | 5 | clonedsql1.post.postid,const | 1 | 100.00 | NULL | | 1 | PRIMARY | editlog | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.postid | 1 | 100.00 | NULL | | 1 | PRIMARY | postparsed | NULL | eq_ref | PRIMARY | PRIMARY | 8 | clonedsql1.post.postid,const,const | 1 | 100.00 | NULL | | 1 | PRIMARY | sigparsed | NULL | eq_ref | PRIMARY | PRIMARY | 8 | clonedsql1.user.userid,const,const | 1 | 100.00 | NULL | | 1 | PRIMARY | sigpic | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.userid | 1 | 100.00 | NULL | | 1 | PRIMARY | post_icon_list | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.postid | 1 | 100.00 | NULL | | 1 | PRIMARY | approvedlog | NULL | eq_ref | PRIMARY | PRIMARY | 546 | clonedsql1.post.postid,const | 1 | 100.00 | NULL | | 1 | PRIMARY | movedlog | NULL | eq_ref | PRIMARY | PRIMARY | 546 | clonedsql1.post.postid,const | 1 | 100.00 | NULL | | 1 | PRIMARY | infraction | NULL | ref | postid | postid | 4 | clonedsql1.post.postid | 1 | 100.00 | NULL | | 1 | PRIMARY | session | NULL | ref | userid | userid | 4 | clonedsql1.user.userid | 364 | 100.00 | Using index | | 1 | PRIMARY | infractionlevel | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.infraction.infractionlevelid | 1 | 100.00 | NULL | | 1 | PRIMARY | scheduled_approval | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.postid | 1 | 100.00 | NULL | | 1 | PRIMARY | additional_user_data | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.userid | 1 | 100.00 | NULL | | 1 | PRIMARY | paid_post_activation | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.post.postid | 1 | 100.00 | NULL | | 1 | PRIMARY | alm_Model_UserData | NULL | eq_ref | PRIMARY | PRIMARY | 4 | clonedsql1.user.userid | 1 | 100.00 | Using where | | 3 | DEPENDENT SUBQUERY | usernote | NULL | ref | userid | userid | 4 | func | 4 | 33.33 | Using where | | 2 | DEPENDENT SUBQUERY | session | NULL | ref | userid | userid | 4 | func | 364 | 33.33 | Using index condition; Using where; Using filesort | +----+--------------------+----------------------+------------+--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ As you can see, the primary key is not used for the joined table 'avatar'. If I add FORCE INDEX FOR JOIN (PRIMARY) for the joined table 'avatar', I get the expected EXPLAIN where the primary key is picked, and the actual query is fast as expected.