1. 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

Discussion in 'Resolved Bug Reports' started by Alan Hollis, Nov 27, 2014.

  1. Alan Hollis

    Alan Hollis New Member

    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
     
  2. Mike

    Mike XenForo Developer Staff Member

    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. Alan Hollis

    Alan Hollis New Member

    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. .Rolex

    .Rolex New Member

    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.
     
  5. Mike

    Mike XenForo Developer Staff Member

    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. Alan Hollis

    Alan Hollis New Member

    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 :)
     
  7. Mike

    Mike XenForo Developer Staff Member

    This is built into 1.4 BTW (as well as having the necessary index changes to support it properly).
     
  8. Alan Hollis

    Alan Hollis New Member

    Thank you Mike! Very much appreciated. We'll upgrade :)
     

Share This Page