• This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn more.

Not a bug Slow query takes down forum

#1
Hi guys,

We got hit with this query yesterday, which took down our forum for a bit...

# Query_time: 360.187542  Lock_time: 0.000075  Rows_sent: 4  Rows_examined: 90466
# Full_scan: No  Full_join: Yes  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0  Priority_queue: Yes
SET timestamp=1416990259;
SELECT post.*
          ,
          bb_code_parse_cache.parse_tree AS message_parsed, bb_code_parse_cache.cache_version AS message_cache_version,
          user.*, IF(user.username IS NULL, post.username, user.username) AS username,
          user_profile.*,
          signature_parse_cache.parse_tree AS signature_parsed, bb_code_parse_cache.cache_version AS signature_cache_version,
          liked_content.like_date, session.view_date
        FROM xf_post AS post
        
          LEFT JOIN xf_bb_code_parse_cache AS bb_code_parse_cache ON
            (bb_code_parse_cache.content_type = 'post' AND bb_code_parse_cache.content_id = post.post_id)
          LEFT JOIN xf_user AS user ON
            (user.user_id = post.user_id)
          LEFT JOIN xf_user_profile AS user_profile ON
            (user_profile.user_id = post.user_id)
          LEFT JOIN xf_bb_code_parse_cache AS signature_parse_cache ON
            (signature_parse_cache.content_type = 'signature' AND signature_parse_cache.content_id = post.user_id)
          LEFT JOIN xf_liked_content AS liked_content
            ON (liked_content.content_type = 'post'
              AND liked_content.content_id = post.post_id
              AND liked_content.like_user_id = 3688)
LEFT OUTER JOIN xf_session_activity AS session ON post.user_id = session.user_id
        WHERE post.thread_id = '5275'
          AND post.post_date > '1369216301'
          AND (post.message_state IN ('visible') OR (post.message_state = 'moderated' AND post.user_id = 3688))
        ORDER BY post.post_date DESC
       LIMIT 4;


Tracing this through the code it looks like it's caused by Thread->actionAddReply(); And specifically the query which gets built in Post->getNewestPostsInThreadAfterDate();

Obviously some kind of index is missing here. I'm wondering if an index on xf_session_activity.user_id is needed?

I'm assuming this is something to do with the session as running the query at other points in the day seems to work fast, and all the indexes are in place

It;s also the only table where a key isn't set, output from explain:

*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: session
type: system
possible_keys: PRIMARY
key: NULL
key_len: NULL
ref: NULL
rows: 0
Extra: const row not found
*************************** 2. row ***************************
id: 1
select_type: SIMPLE
table: post
type: range
possible_keys: thread_id_post_date,thread_id_position,user_id,post_date
key: thread_id_post_date
key_len: 8
ref: NULL
rows: 33708
Extra: Using where
*************************** 3. row ***************************
id: 1
select_type: SIMPLE
table: bb_code_parse_cache
type: eq_ref
possible_keys: content_type_id
key: content_type_id
key_len: 31
ref: const,tfw_xenforo.post.post_id
rows: 1
Extra: Using where
*************************** 4. row ***************************
id: 1
select_type: SIMPLE
table: user
type: eq_ref
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: tfw_xenforo.post.user_id
rows: 1
Extra:
*************************** 5. row ***************************
id: 1
select_type: SIMPLE
table: user_profile
type: eq_ref
possible_keys: PRIMARY
key: PRIMARY
key_len: 4
ref: tfw_xenforo.post.user_id
rows: 1
Extra:
*************************** 6. row ***************************
id: 1
select_type: SIMPLE
table: signature_parse_cache
type: eq_ref
possible_keys: content_type_id
key: content_type_id
key_len: 31
ref: const,tfw_xenforo.post.user_id
rows: 1
Extra: Using where
*************************** 7. row ***************************
id: 1
select_type: SIMPLE
table: liked_content
type: eq_ref
possible_keys: content_type_id_like_user_id,like_user_content_type_id
key: content_type_id_like_user_id
key_len: 35
ref: const,tfw_xenforo.post.post_id,const
rows: 1
Extra: Using where

I'm not hugely familiar with the xenforo code base, so hopefully someone who is will be able to give me a better idea as to why this happened and what we can do to mitigate it!

Thank you,

Alan
 

Mike

XenForo developer
Staff member
#2
We actually had another report of this recently via a ticket. I didn't think anything of it at the time but the session activity code there is not the standard XF code for that, so there's an add-on involved.

Make sure you're running the latest version (as there were index changes on the session activity table as well) and can confirm the issue without add-ons. You can check it by replying on the first page of a long thread.
 
#3
How would an addon get involved with this part of the code? The two files are XenForo/Model.php and Xenforo/Post.php, and I can't see any hooks within the methods that are involved in building that query. I could of course be being blind...

Hopefully that reads the right way, difficult to get the tone right ;) , but I'm curious to how this works! As stated my XenForo experience is pretty limited :)
 
#4
How would an addon get involved with this part of the code? The two files are XenForo/Model.php and Xenforo/Post.php, and I can't see any hooks within the methods that are involved in building that query. I could of course be being blind...

Hopefully that reads the write way, difficult to get the tone right ;) , but I'm curious to how this works! As stated my XenForo experience is pretty limited :)
I guess the only way to isolate which add-on is causing the problem would be to disable them one by one and do the test Mike suggested. The one disabled before the issue is solved would be your culprit.
 

Mike

XenForo developer
Staff member
#5
Add-ons can extend classes.

You can see how this query is built in those files. If you search for "LEFT OUTER JOIN", you won't find it. If you search for "session.view_date", you won't find it. Both of these point to an add-on manipulating the query.
 
#6
Awesome thanks Mike :) Perfect :)

vagrant@web1:/srv/www/sites/public$ grep -R "LEFT OUTER JOIN" *
library/Zend/Db/Adapter/Pdo/Pgsql.php: LEFT OUTER JOIN pg_constraint AS co ON (co.conrelid = c.oid
library/Zend/Db/Adapter/Pdo/Pgsql.php: LEFT OUTER JOIN pg_attrdef AS d ON d.adrelid = c.oid AND d.adnum = a.attnum
library/Zend/Db/Select.php: * Add a LEFT OUTER JOIN table and colums to the query
library/Asp/OnlineStatus/Model/AspPost.php: $array['joinTables'] .= 'LEFT OUTER JOIN xf_session_activity AS session ON post.user_id = session.user_id';


I now know the culprit :)
 

Mike

XenForo developer
Staff member
#7
This is built into 1.4 BTW (as well as having the necessary index changes to support it properly).