Support Forum

RSS creates long and slow query errors

KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 29, 2014 · 7:12 am · Edited

Hey guys, was looking at my server error log (not the forum error log) and noticed that the rss is generating long and slow querys, here is examples of the errors, is this a concern? 

[Wed Oct 29 10:44:06 2014] [error] [client xx.xxx.xx.xx] [WPE Monitoring] Stopwatch php.pod-2294.function.mysql_query.duration exceeded 1000ms. Was: 2866ms.
#0 wpe\measure\LoggingStopwatch->logStackTrace(2866) called at [/nas/wp/www/common/production/measure.php:198]
#1 wpe\measure\LoggingStopwatch->lap_ended(2866) called at [/nas/wp/www/common/production/measure.php:134]
#2 wpe\measure\Stopwatch->lapstart() called at [/nas/wp/www/common/production/measure.php:152]
#3 wpe\measure\Stopwatch->stop() called at [/nas/wp/www/common/production/statsd_monitoring.php(256) : runkit created function:19]
#4 mysql_query(SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id,
tttttttt rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name,
tttttttt topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15 /* From [thehomesteadingboards.com/forums/rss/] in [/nas/wp/www/cluster-2294/xxxxxx/wp-content/plugins/simple-press/sp-api/sp-api-wpdb.php:176] */, Resource id #28) called at [/nas/wp/www/cluster-2294/xxxxx/wp-includes/wp-db.php:1655]
#5 wpdb->_do_query(SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id,
tttttttt rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name,
tttttttt topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15 /* From [thehomesteadingboards.com/forums/rss/] in [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/sp-api/sp-api-wpdb.php:176] */) called at [/nas/wp/www/cluster-2294/xxxxx/wp-includes/wp-db.php:1559]
#6 wpdb->query(SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id,
tttttttt rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name,
tttttttt topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15) called at [/nas/wp/www/cluster-2294/xxxxx/wp-includes/wp-db.php:1950]
#7 wpdb->get_results(SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id,
tttttttt rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name,
tttttttt topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15, OBJECT) called at [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/sp-api/sp-api-wpdb.php:176]
#8 spdb_select(set, SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id,
tttttttt rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name,
tttttttt topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15, OBJECT) called at [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/sp-api/sp-api-wpdb.php:308]
#9 spdbComplex->select() called at [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/forum/content/classes/sp-list-post-class.php:154]
#10 spPostList->sp_postlistview_query(rufus_sfforums.forum_rss_private = 0, rufus_sfposts.post_id DESC, 15, post-content) called at [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/forum/content/classes/sp-list-post-class.php:80]
#11 spPostList->__construct(rufus_sfforums.forum_rss_private = 0, rufus_sfposts.post_id DESC, 15, post-content) called at [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/forum/feeds/sp-feeds.php:87]
#12 include(/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/forum/feeds/sp-feeds.php) called at [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/sp-startup/site/sp-site-support-functions.php:258]
#13 sp_feed()
#14 call_user_func_array(sp_feed, Array ([0] => )) called at [/nas/wp/www/cluster-2294/xxxxx/wp-includes/plugin.php:505]
#15 do_action(template_redirect) called at [/nas/wp/www/cluster-2294/xxxxx/wp-includes/template-loader.php:12]
#16 require_once(/nas/wp/www/cluster-2294/xxxxx/wp-includes/template-loader.php) called at [/nas/wp/www/cluster-2294/xxxxx/wp-blog-header.php:16]
#17 require(/nas/wp/www/cluster-2294/xxxxx/wp-blog-header.php) called at [/nas/wp/www/cluster-2294/xxxxx/index.php:17]

[Wed Oct 29 10:44:06 2014] [error] [client xx.xxx.xx.xx] [WPE Monitoring] Slow mysql_query() call was running query:
SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id,
tttttttt rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name,
tttttttt topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15 /* From [thehomesteadingboards.com/forums/rss/] in [/nas/wp/www/cluster-2294/xxxxx/wp-content/plugins/simple-press/sp-api/sp-api-wpdb.php:176] */

52 Answers

New Answer
YS Yellow Swordfish
Yellow Swordfish
Member
Member since Nov 2008
16,437 posts
Oct 29, 2014 · 9:56 am

I see 2 errors mentioned. It is rather a shame that there is no attempt to diagnose why they took so long. I don not believe there is anything more complex about RSS queries than any other to be frank.

So – why were they slow? Well – first thing to check would be the database tables to ensure there are none that need a good optimisation. Bad data fragmentation can kill queries. But it could also simply be that there was a lot going on when the queries were made and the database was under fierce contention… I don’t know if that is likely. But I would check the tables first.

KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 29, 2014 · 10:09 am

 I run wp-optimize weekly and select all the tables through php myadmin monthly and select all the tables and optimize them, would it be because some of the tables are InnoDB? If I try to optimize those I get this

Table does not support optimize, doing recreate + …

but then it shows okay right below it

I had contacted wpengine, they said it really wasn’t a error, it’s just to show what may be causing performance issues

Those two errors are what shows in the log anytime someone tries to access the forum feed

YS Yellow Swordfish
Yellow Swordfish
Member
Member since Nov 2008
16,437 posts
Oct 29, 2014 · 3:16 pm

And it doesn’t look problematic, Strange.

Are you seeing any corresponding errors or entries in the php error log to do with the Db query?

KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 29, 2014 · 5:16 pm

not seeing php errors that I know of, just these query issues

MP Mr Papa
Mr Papa
Member
Member since Dec 2006
19,448 posts
Oct 29, 2014 · 9:33 pm

yeah, strange… are you using the rss feeds out of the box? some folks use filters to modify which can slow down, though wouldnt think that was the query itself…

is that the All RSS feed?  how many groups and forums do you have?

KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 30, 2014 · 6:27 am

yes the all rass, just out of the box, 3 group, 14 forums total, had the rss feed set at 15 topics

YS Yellow Swordfish
Yellow Swordfish
Member
Member since Nov 2008
16,437 posts
Oct 30, 2014 · 8:11 am

You can probably guess that both Steve and I are at a loss to understand why this should be slow!

Would you be able to run the query outside of WordPress – i,e., using phpMyAdmin for example – to see if it runs OK there – or messages out? Possible?

YS Yellow Swordfish
Yellow Swordfish
Member
Member since Nov 2008
16,437 posts
Oct 30, 2014 · 8:28 am

Sorry. I am assuming it is the one in the log you publshed above:

SELECT rufus_sfposts.post_id, post_content, post_date, rufus_sfposts.topic_id, rufus_sfposts.forum_id, rufus_sfposts.user_id, guest_name, post_status, post_index, forum_name, forum_slug, forum_disabled, rufus_sfforums.group_id, group_name, topic_name, topic_slug, rufus_sftopics.post_count, topic_opened, display_name FROM rufus_sfposts JOIN rufus_sfforums ON rufus_sfforums.forum_id = rufus_sfposts.forum_id JOIN rufus_sfgroups ON rufus_sfgroups.group_id = rufus_sfforums.group_id JOIN rufus_sftopics ON rufus_sftopics.topic_id = rufus_sfposts.topic_id LEFT JOIN rufus_sfmembers ON rufus_sfmembers.user_id = rufus_sfposts.user_id WHERE rufus_sfforums.forum_rss_private = 0 AND rufus_sfposts.forum_id IN (5849,5850,5851,5852,5853,5854,5855,5856,5857,5858,5859,5863,5864) ORDER BY rufus_sfposts.post_id DESC LIMIT 15
KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 30, 2014 · 8:48 am

ran it on my staging server phpmyadmin, here was the results (15 total, Query took 1.6839 seconds.)

I accessed the feed through a feed reader and the errors showed in the error log, but not when I ran the sql query, feed reader took 2.003 seconds

KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 30, 2014 · 9:05 am

I tried cutting back on the amount it was showing in the feed, I dropped it to 10, then 5, and they were 1.9 and 1.7 seconds for the query, I then limited the feed to just topic names to see if that fixed it, and just the 10 topic names were above 2 seconds for the query

MP Mr Papa
Mr Papa
Member
Member since Dec 2006
19,448 posts
Oct 30, 2014 · 8:34 pm

interesting that a feed reader increases the queries (not sure why)??

there is nothing special about the feed, especially if only 5 items?  way less complex a query than you forum front page…  and getting several times an order of magnitude less than that myself…

may need Andy to jump in here, but when you do it on your staging server, can you have it do an explain?  will give more info about what the query is trying to do and may offer insight…

also might be useful to see your keys for the sfgroup, sfforum and sftopic tables… make sure indexes look right… though if not, would expect the main forum view queries to be very poor then…

KV kvr28
kvr28
Member
Member since Mar 2014
804 posts
Oct 30, 2014 · 8:44 pm

here is the explain

1 SIMPLE rufus_sfgroups ALL PRIMARY NULL NULL NULL 3 Using temporary; Using filesort
1 SIMPLE rufus_sfforums ref PRIMARY,groupf_idx groupf_idx 8 snapshot_kvr28.rufus_sfgroups.group_id 5 Using where
1 SIMPLE rufus_sfposts ref topicp_idx,forump_idx forump_idx 8 snapshot_kvr28.rufus_sfforums.forum_id 1138  
1 SIMPLE rufus_sftopics eq_ref PRIMARY PRIMARY 8 snapshot_kvr28.rufus_sfposts.topic_id 1  
1 SIMPLE rufus_sfmembers eq_ref PRIMARY PRIMARY 8 snapshot_kvr28.rufus_sfposts.user_id 1  
MP Mr Papa
Mr Papa
Member
Member since Dec 2006
19,448 posts
Oct 30, 2014 · 8:55 pm

a temp table and filesort, eh?  seems bit overkill, but as I said, may need input from Andy…

are you suing MyISAM or InnoDB tables? 

oh,and can you paste in your my.ini setup?  be sure no passwords or other private info in what you post… ;)