Forum

Thread tagged as: Problem, Runway

Slow loading blog list page

I have a Runway installation running Blog 5.0 with ~800 blog posts imported from Wordpress. My blog index page is loading more slowly than my other Runway installs (on both dev and staging) and I'm trying to figure out why. This listing page is more complex than usual, with several perch_blog_custom() outputs as well as perch_categories() and perch_blog_authors(). Still, I don't feel that the page is heavy enough to be loading 6 seconds slower than usual.

Here is the debug message with PERCH_PRODUCTION_MODE set to PERCH_DEVELOPMENT:

Time    Δ   Debug Message
0.1005  0   [18] SELECT p.pagePath, pr.routePattern, pr.routeRegExp, p.pageTemplate FROM perch2_pages p LEFT JOIN perch2_page_routes pr ON p.pageID=pr.pageID ORDER BY pr.routeOrder ASC, p.pagePath ASC
0.1018  0.0013  Matched page: /blog, so not using routes.
0.102   0.0002  Using master page: /templates/pages/blog/index.php
0.1101  0.0081  [1] SELECT * FROM perch2_pages WHERE pagePath='/blog' LIMIT 1
0.1142  0.0041  Using template: /templates/pages/attributes/default.html
0.1153  0.0011  Using sub-template: /templates/pages/attributes/seo.html
0.1229  0.0076  [1] SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID' JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-22 06:30:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 0, 1
2.2912  2.1684  [25] SELECT DISTINCT settingID, settingValue FROM perch2_settings WHERE userID=0
2.2942  0.003   [1] Using template: /templates/blog/_post_top.html
2.2979  0.0037  [131] SELECT * FROM perch2_blog_authors ORDER BY authorFamilyName, authorGivenName ASC
2.307   0.0091  [1] SELECT * FROM perch2_blog_sections ORDER BY sectionTitle ASC
2.3091  0.002   [1] SELECT * FROM perch2_blogs ORDER BY blogTitle ASC
2.3149  0.0059  [1] SELECT regionID, regionTemplate, regionPage, regionRev AS rev FROM perch2_content_regions WHERE regionKey='Contact Information' AND (regionPage='/blog' OR regionPage='*')
2.3154  0.0005  [1] SELECT * FROM ( SELECT idx.itemID, c.regionID, idx.pageID, c.itemJSON, idx2.indexValue as sortval FROM perch2_content_index idx JOIN perch2_content_items c ON idx.itemID=c.itemID AND idx.itemRev=c.itemRev AND idx.regionID=c.regionID JOIN perch2_content_index idx2 ON idx.itemID=idx2.itemID AND idx.itemRev=idx2.itemRev AND idx2.indexKey='_order' WHERE ((idx.regionID=12 AND idx.itemRev=3)) AND idx.itemID=idx2.itemID AND idx.itemRev=idx2.itemRev ) as tbl GROUP BY itemID, pageID, itemJSON, sortval ORDER BY sortval ASC
2.3159  0.0004  [1] Using template: /templates/content/shared/_hero_social.html
2.3176  0.0018  [1] SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID' JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-22 06:30:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 1, 1
4.6368  2.3192  [1] Using template: /templates/blog/_post_hero.html
4.6469  0.0101  [1] SELECT setID FROM perch2_category_sets WHERE setSlug='blog' LIMIT 1
4.6474  0.0005  [35] SELECT main.* FROM perch2_categories main WHERE 1=1 AND setID=1 ORDER BY catTitle ASC
4.6504  0.0031  [35] Using template: /templates/categories/blog_list_nav.html
4.6831  0.0327  [130] SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx JOIN perch2_blog_authors main ON idx.itemID=main.authorID AND idx.itemKey='authorID' JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='authorID' AND idx2.indexKey='authorGivenName' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (authorPostCount>0) GROUP BY itemID, sortval ORDER BY sortval ASC
4.6885  0.0054  [130] Using template: /templates/blog/_author_list_nav.html
4.8423  0.1538  [6] SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID' JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-22 06:30:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 2, 6
7.0195  2.1772  [6] Using template: /templates/blog/post_in_list.html
7.0219  0.0024  [5] SELECT * FROM perch2_categories ORDER BY catTreePosition ASC
7.0548  0.0329  [4] SELECT regionKey, regionHTML FROM perch2_content_regions WHERE regionPage='/blog' OR regionPage='*' ORDER BY regionPage DESC
7.0555  0.0007  [1] SELECT * FROM ( SELECT idx.itemID, c.regionID, idx.pageID, c.itemJSON, idx2.indexValue as sortval FROM perch2_content_index idx JOIN perch2_content_items c ON idx.itemID=c.itemID AND idx.itemRev=c.itemRev AND idx.regionID=c.regionID JOIN perch2_content_index idx2 ON idx.itemID=idx2.itemID AND idx.itemRev=idx2.itemRev AND idx2.indexKey='_order' WHERE ((idx.regionID=12 AND idx.itemRev=3)) AND idx.itemID=idx2.itemID AND idx.itemRev=idx2.itemRev ) as tbl GROUP BY itemID, pageID, itemJSON, sortval ORDER BY sortval ASC
7.0559  0.0005  [1] Using template: /templates/content/shared/_footer.html
7.0588  0.0029  [5] SELECT * FROM perch2_pages WHERE pageNew=0 AND pageHidden=0 AND pageDepth >=0 AND pageDepth<=1 ORDER BY pageTreePosition ASC
7.0595  0.0006  [1] SELECT pageTreePosition FROM perch2_pages WHERE pagePath='/blog' LIMIT 1
7.0598  0.0003  [1] SELECT pageID FROM perch2_pages WHERE pageTreePosition IN ('000-003', '000') ORDER BY pageTreePosition DESC
7.0604  0.0006  [5] Using template: /templates/navigation/primary_nav.html
7.0674  0.007   Request time: 7.0672
7.0675  0.0001  Process time: 7.0663
7.0676  0.0001  Memory: 4.8611
7.0677  0.0001  
Array
(
    [type] => 32
    [message] => PHP Startup: Unable to load dynamic library '/usr/local/lib/php/extensions/no-debug-non-zts-20131226/ffmpeg.so' - /usr/local/lib/php/extensions/no-debug-non-zts-20131226/ffmpeg.so: cannot open shared object file: No such file or directory
    [file] => Unknown
    [line] => 0
)

(I only get the ffmpeg.so error on staging, but the site loads slow on dev as well)

This is my page:

<?php   
// 'load more' link
if (perch_get('ajax') && perch_get('start')) {
    perch_blog_custom(array(
      'template' => 'post_in_list.html',
      'count'=>6,
      'start'=>perch_get('start'),
      'sort'=>'postDateTime',
      'sort-order'=>'DESC',
      'paginate'=>false,
    ));
}
// begin page
else {

perch_layout('global/header',[
    'body-class'=>'blog-index'
]);
PerchSystem::set_var('blog-index', 'true');
perch_blog_custom(array(
  'template' => '_post_top.html',
  'count'=>1,
  'sort'=>'postDateTime',
  'sort-order'=>'DESC',
  'paginate'=>false,
));
perch_content_custom('Contact Information',[
    'template'=>'shared/_hero_social.html'
]);
echo '</div>'; /* closed from _post_top.html */
?>

<div class="section white-bg no-pad page-wrap">
    <div class="section split-hero dd-nav-wrap title-bg">
        <div class="container no-pad">
            <div>
                <div class="hero-title darker-gray-bg"><h2>Recent Posts</h2></div>
                <?php perch_blog_custom(array(
                  'template' => '_post_hero.html',
                  'count'=>1,
                  'start'=>2,
                  'sort'=>'postDateTime',
                  'sort-order'=>'DESC',
                  'paginate'=>false,
                )); ?>
            </div><div>
                <div class="hero-title dark-gray-bg"><h2>Search the Blog</h2></div>
                <?php 
                    perch_categories([
                      'set' => 'blog',
                      'template' => 'blog_list_nav.html',
                      'sort' => 'catTitle',
                      'sort-order' => 'ASC',
                      'paginate' => false,
                    ]);
                    perch_blog_authors([
                      'template' => '_author_list_nav.html',
                      'sort' => 'authorGivenName',
                      'sort-order' => 'ASC',
                      'paginate' => false,
                    ]);
                ?>
                <div class="section darker-gray-bg dd-nav-wrap alrightsans blog-search-wrap">
                    <form id="blog_search" action="/blog/search" method="get">
                        <div>
                            <label for="q">By Keyword...</label>
                            <input type="text" id="q" name="q" class="darker-gray-bg alrightsans" required>
                            <button type="submit" class="darker-gray-bg" ><span class="icon-arrow-right"></span></button>
                        </div>
                    </form>
                </div>
            </div>
        </div>
    </div>
    <div class="section light-gray-bg posts-in-list">
        <div class="container" id="loadWrap">
            <?php perch_blog_custom(array(
              'template' => 'post_in_list.html',
              'count'=>6,
              'start'=>3,
              'sort'=>'postDateTime',
              'sort-order'=>'DESC',
              'paginate'=>false,
            )); ?>
        </div>
    </div>
    <div class="section">
        <div class="container text-center">
            <span class="blue alrightsans" href="javascript:void(0)" data-url="/blog?" data-start="9" id="loadMore">Load More Posts +</span>
        </div>
    </div>
</div>

<?php
perch_layout('global/footer',[
    'scripts'=>'<script>jQuery(document).ready(function(){$("#blog_search label").inFieldLabels({fadeDuration:200});});</script><script type="text/javascript" src="/js/incl_blog-list-load.js?v=2016112101"></script><script type="text/javascript" src="/js/incl_dd-list-nav.js?v=2016112101"></script>'
]);

}

and diagnostics:

Diagnostics report
HEALTH CHECK

Perch Runway is up to date
PHP 5.6.24 is up to date
MySQL 5.5.52-cll is up to date
Image processing available
SUMMARY INFORMATION

Perch Runway: 2.8.32, PHP: 5.6.24, MySQL: mysqlnd 5.0.11-dev - 20120503 - $Id: 76b08b24596e12d4553bd41fc93cccd5bac2fe7a $, with PDO
Server OS: Linux, litespeed
Installed apps: content (2.8.32), assets (2.8.32), categories (2.8.32), perch_blog (5.0), collection_3 (2.8.32)
App runtimes: <?php $apps_list = array( 'content', 'categories', 'perch_blog', );
PERCH_LOGINPATH: /ifs-admin
PERCH_PATH: /home/mttstage/public_html/ifs/ifs-admin
PERCH_CORE: /home/mttstage/public_html/ifs/ifs-admin/core
PERCH_RESFILEPATH: /home/mttstage/public_html/ifs/ifs-admin/resources
Image manipulation: GD
PHP limits: Max upload 64M, Max POST 64M, Memory: 128M, Total max file upload: 64M
F1: 2edba60ed1f613d6dd804feb202456a2
Resource folder writeable: Yes
HTTP_HOST: ifs.staging.mytechtailor.com
DOCUMENT_ROOT: /home/mttstage/public_html/ifs
REQUEST_URI: /ifs-admin/core/settings/diagnostics/
SCRIPT_NAME: /ifs-admin/core/settings/diagnostics/index.php

Is there anything else that would be useful for troubleshooting? Thanks for the help!

Shane Lenzen

Shane Lenzen 18 points

  • 4 years ago

I forgot to mention that subsequent page loads are much faster, even with browser cache disabled. The first load is very slow, but then when I refresh the page with browser cache disabled, it loads almost instantly. It continues to load very quickly on refresh until about 60 seconds from the initial load, and then it loads slow again, then fast for the next 60 seconds and so on. I see this behavior even when I simplify the page to just this:

perch_blog_custom(array(
'template' => 'post_in_list.html',
'count'=>6,
'sort'=>'postDateTime',
'sort-order'=>'DESC',
'paginate'=>false,
));

My other Runway sites load almost instantly with a blog listing like that, so I definitely think something is wrong. Here is post_in_list.html FYI:

<div class="post-in-list"><a href="<perch:blog id="postURL" type="hidden" />"><span><span style="background-image:url('<perch:blog order="3" id="feat_img" type="image" width="600" quality="90" label="Featured Image" bucket="blog" divider-before="Options" required="true" />');"></span></span>
  <h3 class="alrightsanslight"><perch:blog order="1" id="postTitle" type="text" label="Title" required="true" size="xl autowidth" /></h3></a>
  <perch:if exists="authorGivenName"><div class="author alrightsans">
   by <a href="/blog/author/<perch:blog id="authorSlug" type="text" />"><perch:blog id="authorGivenName" type="hidden" /> <perch:blog id="authorFamilyName" type="hidden" /></a>
  </div></perch:if>
  <perch:categories order="7" id="categories" set="blog" label="Categories" display-as="checkboxes" ><perch:before><div class="categories alrightsans"></perch:before><span><a href="/blog/category/<perch:category id="catSlug" type="slug" />"><perch:category id="catTitle" type="text" /></a><perch:if not-exists="perch_item_last">, </perch:if></span><perch:after></div></perch:after></perch:categories></div>
Drew McLellan

Drew McLellan 2638 points
Perch Support

Do you know much about how your MySQL server is configured?

Both dev and staging are standard MySQL configs as far as I know. I have root access to both systems, is there anything in particular you need to know? Other Perch/Runway sites on the same servers are speedy as ever.

Drew McLellan

Drew McLellan 2638 points
Perch Support

It sounds like the query cache is working, but perhaps the result isn't being cached for that long.

It may be an issue of scale - we have some changes coming for Runway 3.0 that will really improve these slower queries.

Do you think 800 blog posts is enough to slow it down by several seconds? Anything else I should check? We're launching in a week and the site gets a decent amount of traffic (3k visitors/day) so if you can think of anything I can do to speed it up before Runway 3.0, I would really appreciate it!

Drew McLellan

Drew McLellan 2638 points
Perch Support

Are you indexing all the fields in the blog posts, and if so, do you need to filter by them all? Reducing the size of the index could help.

Thanks Drew. So you would recommend I add no-index="true" to all fields that are not used for filtering, right? Does that include filtering by 'match'=>'contains'? Is there a way for me to republish all blog posts at once to remove these fields from the index?

Drew McLellan

Drew McLellan 2638 points
Perch Support

Yes, you can go to /perch_blog/update/ and run the updater, which will reindex the posts.

Thanks Drew. I can only add no-index="true" to a repeater and the featured image, since I'm filtering by or searching all other fields. I added no-index and ran the updater, but it didn't seem to help. I did notice that this query:

    perch_blog_custom(array(
      'template' => 'post_in_list.html',
      'count'=>6,
      'start'=>perch_get('start'),
      'sort'=>'postDateTime',
      'sort-order'=>'DESC',
      'paginate'=>false,
    ));

runs slower than the same query filtered by category:

    perch_blog_custom(array(
      'template' => 'post_in_list.html',
      'count'=>6,
      'start'=>perch_get('start'),
      'sort'=>'postDateTime',
      'sort-order'=>'DESC',
      'paginate'=>false,
      'category'=>'blog/'.perch_get('category')
    ));

Isn't that strange? Here is the slow query log in case it provides any more insight. Thanks again for the help and please let me know if you think there's anything else I can do.

# Time: 161123 14:32:27
# User@Host: mttstage_ifstudi[mttstage_ifstudi] @ localhost []
# Query_time: 1.616453 Lock_time: 0.000206 Rows_sent: 1 Rows_examined: 48137
SET timestamp=1479933147;
SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx
JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID'
JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-23 20:32:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 1, 1;
# Time: 161123 14:32:29
# User@Host: mttstage_ifstudi[mttstage_ifstudi] @ localhost []
# Query_time: 1.727835 Lock_time: 0.000390 Rows_sent: 6 Rows_examined: 48143
SET timestamp=1479933149;
SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx
JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID'
JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-23 20:32:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 2, 6;
# Time: 161123 14:33:04
# User@Host: mttstage_ifstudi[mttstage_ifstudi] @ localhost []
# Query_time: 1.811988 Lock_time: 0.000214 Rows_sent: 1 Rows_examined: 48136
SET timestamp=1479933184;
SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx
JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID'
JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-23 20:33:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 0, 1;
# Time: 161123 14:33:06
# User@Host: mttstage_ifstudi[mttstage_ifstudi] @ localhost []
# Query_time: 1.638074 Lock_time: 0.000149 Rows_sent: 1 Rows_examined: 48137
SET timestamp=1479933186;
SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx
JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID'
JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-23 20:33:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 1, 1;
# Time: 161123 14:33:07
# User@Host: mttstage_ifstudi[mttstage_ifstudi] @ localhost []
# Query_time: 1.590688 Lock_time: 0.000163 Rows_sent: 6 Rows_examined: 48143
SET timestamp=1479933187;
SELECT tbl.* FROM ( SELECT idx.itemID, main.*, idx2.indexValue as sortval FROM perch2_blog_index idx
JOIN perch2_blog_posts main ON idx.itemID=main.postID AND idx.itemKey='postID'
JOIN perch2_blog_index idx2 ON idx.itemID=idx2.itemID AND idx.itemKey='postID' AND idx2.indexKey='postDateTime' WHERE 1=1 AND idx.itemID=idx2.itemID AND idx.itemKey=idx2.itemKey ) as tbl WHERE (postStatus='Published' AND postDateTime<='2016-11-23 20:33:00' ) GROUP BY itemID, sortval ORDER BY sortval DESC LIMIT 2, 6;
Drew McLellan

Drew McLellan 2638 points
Perch Support

Did your index drop in size?

It's not strange that it runs slower when you're filtering by category - it's doing more work.

The index did drop in size a little. Filtering by category runs faster! Very odd.

Drew McLellan

Drew McLellan 2638 points
Perch Support

I guess that could be the case, depending on the execution plan for the query. Show you have to try these things rather than assume!