Controller Execution Time on Page Loads Extremely Slow

#1 / Feb 21, 2012 7:36pm
l3training
20 posts
I have been troubleshooting our install of EE2.3.1, Build: 20111017 for a couple days now and cannot seem to pinpoint where the issue is with our site loading so slow. I have turned on Output Profiler and Template Debugging and the output is as follows:
```
Loading Time: Base Classes   0.0030
Controller Execution Time ( Ee / Index )   17.4297
Total Execution Time   17.4329
```
The template debugging output shows that:
```
(0.000011 / 0.86MB) - Begin Template Processing -
(17.011323 / 0.87MB) URI:
(17.011350 / 0.87MB) Path.php Template: site/index
```
I have tried the following:

- disabling third party addons
- disabled unnecessary template/channel/entry features
- turned template cache on/off

The SQL queries total under 0.003 seconds so it is not the database and the CP pages load relatively fast (under 1-2sec) so it is not really the server bandwidth. I have tried testing the same HTML, JS and images from the home page on a different server and it loads under 2sec so its not the HTML code per se. I also tried to create a static template of our home page with the entire HTML code loaded into the template. Still takes over 18sec to load the page with no embeds, no snippets or any EE addons.

I am completely stumped and would appreciate any other help in troubleshooting the reason the Controller Execution Time is so slow.
#2 / Feb 21, 2012 9:42pm

l3training
20 posts

I have also tried disabling Generate HTTP Page Headers and no change in load speed.
#3 / Feb 22, 2012 5:47pm

Dan Decker
7338 posts

Hi Matt,

Can you post the template code that is causing the long load time?

Do you notice this on several templates, or one in particular?

I had a similar issue once where the template used several conditionals to evaluate some values. It took nearly 14secs to load. Are you using any advanced conditionals on the templates that are affected?

Cheers,

#4 / Feb 22, 2012 7:31pm

l3training

20 posts

And the last embedded template for the includes/footer_global:

<!-- ======================== FOOTER COMPASS ======================== --> 
<div id="footer">
<div class="footer-area">
<div class="footer-wrapper">
<div class="footer-holder">

 {exp:channel:entries channel="menus" entry_id="64" disable="categories|member_data|pagination"}
   
<div class="one_fifth_first">
 <h3>Solutions</h3>
<p> <div class="panel-wrap"><br />
  <ul class="widgetlinks">{menu_items}{if parent_category == 'Solutions' && menu_footer != 'y' }<li><a href="http://{path=%27{menu_url}%27}" title="{menu_title}">{menu_title}</a></li>{/if}{/menu_items}</ul></div><!-- / panel-wrap --></div><!-- end first one_fifth_column --></p>

<p><div class="one_fifth"></p><h3>Applications</h3>
<p> <div class="panel-wrap"><br />
  <ul class="widgetlinks">{menu_items}{if parent_category == 'Applications' && menu_footer != 'y' }<li><a href="http://{path=%27{menu_url}%27}" title="{menu_title}">{menu_title}</a></li>{/if}{/menu_items}</ul></div><!-- / panel-wrap --><br />
</div><!-- end second one_fifth_column --></p>

<p><div class="one_fifth"></p><h3>Why Choose L-3</h3>
<p> <div class="panel-wrap"><br />
  <ul class="widgetlinks">{menu_items}{if parent_category == 'Why Choose' && menu_footer != 'y' }<li><a href="http://{path=%27{menu_url}%27}" title="{menu_title}">{menu_title}</a></li>{/if}{/menu_items}</ul></div><!-- / panel-wrap --><br />
</div><!-- end third one_fifth_column --></p>

<p><div class="one_fifth"></p><h3>Resources</h3>
<p>    <div class="panel-wrap"><br />
  <ul class="widgetlinks">{menu_items}{if parent_category == 'Resources' && menu_footer != 'y' }<li><a href="http://{path=%27{menu_url}%27}" title="{menu_title}">{menu_title}</a></li>{/if}{/menu_items}</ul></div><!-- / panel-wrap --><br />
</div><!-- end fourth one_fifth_column --></p>

<p><div class="one_fifth_last"><br />
  </p><h3>About Us</h3>
<p> <div class="panel-wrap"><br />
  <ul class="widgetlinks">{menu_items}{if parent_category == 'About Us' && menu_footer != 'y' }<li><a href="http://{path=%27{menu_url}%27}" title="{menu_title}">{menu_title}</a></li>{/if}{/menu_items}</ul></div><!-- / panel-wrap --><br />
</div><!-- end last one_fifth_column --></p>

<p>{/exp:channel:entries}</p>

<p></div><!-- footer-holder --><br />
</div><!-- end footer-wrapper --><br />
</div><!-- end footer-area --><br />
</div><!-- end footer --></p>

<p><!-- /======================== END FOOTER COMPASS ======================== --> </p>

<p><!-- /======================== Global Footer  ======================== --> </p>

<p><div id="footer_bottom"><br />
 <div class="info"><br />
 <div id="foot_left">{snp_footer_legals}</div><!-- end foot_left --><br />
 <div id="foot_right"><br />
   <div class="top-footer"><a href="http://www.l-3com.com">{site_url}_assets/images/_global/logo_footer.gif</a></div><br />
    {snp_footer_copyright}<br />
   </div><!-- end foot_right --><br />
 </div><!-- end info --><br />
</div><!-- end footer_bottom --></p>

<p><!-- /======================== END Global Footer ======================== --> </p>

<p></div><!-- end main --></p>

<p></div><!-- end wrapper --></p>

<p>{snp_footer_js}</p>

<p></body><br />
</html>

#8 / Feb 24, 2012 3:28pm

Robin Sowell
13255 posts

I don’t think I’ve ever seen a debug bog down in that way. If you make a blank template- nothing on it but ‘Hello world’ text- and load it- what do you get for the template debug output? It looks like you slow way down before it ever even starts tag processing. And out of curiosity- does a regular html page load up slow? Do you have an htaccess file in place? If you temporarily remove it, does it make any difference? How about extensions- if you disable extensions, does it make a difference? (I know you mentioned disabling add-ons, but I want to be sure you did it disabling extensions, as they’re a likely culprit.)

I’m off to take a look at what happens between:
(0.000006 / 0.83MB) - Begin Template Processing -
(0.000167 / 0.83MB) URI: about/test

Well- what happens that might be taking 17 seconds!
#9 / Feb 27, 2012 7:19pm
l3training
20 posts
I went ahead and setup a blank text file in the template site/helloworld, accessible at http://www.l-3training.com/site/helloworld. Results as follows:
```
BENCHMARKS  
Loading Time: Base Classes   0.0140
Controller Execution Time ( Ee / Index )   22.8120
Total Execution Time   22.8262
```
I attached the remainder of the template debugging output. Interestingly enough there is a lot of snippets code loading. There are no snippets on this new template and it is the same on any other page that loads. Any ideas?

#10 / Feb 29, 2012 11:11am

Robin Sowell

13255 posts

Sorry for the delay! OK- I’d bet it’s failing to clear cache- let’s see if this speeds things up. It is not a fix- but it will tell us if this is the problem.

You’ll need to open up system/expressionengine/libraries/Template.php in a text editor- and look around line 154:

// We limit the total number of cache files in order to
  // keep some sanity with large sites or ones that get
  // hit by over-ambitious crawlers.
  if ($this->disable_caching == FALSE)
  {  
   if ($dh = @opendir(APPPATH.'cache/page_cache'))
   {
    $i = 0;
    while (FALSE !== (readdir($dh)))
    {
     $i++;
    }
    
    $max = ( ! $this->EE->config->item('max_caches') OR ! is_numeric($this->EE->config->item('max_caches')) OR $this->EE->config->item('max_caches') > 1000) ? 1000 : $this->EE->config->item('max_caches');
    
    if ($i > $max)
    {
     $this->EE->functions->clear_caching('page');
    }
   }
  }
  
  $this->log_item("URI: ".$this->EE->uri->uri_string);

We’re going to comment out the page caching and see if it matters. (If it doesn’t- we’ll comment out some more. So- look for this bit and comment it out by putting // before it- so the code now looks like:

// We limit the total number of cache files in order to
  // keep some sanity with large sites or ones that get
  // hit by over-ambitious crawlers.
  if ($this->disable_caching == FALSE)
  {  
   if ($dh = @opendir(APPPATH.'cache/page_cache'))
   {
    $i = 0;
    while (FALSE !== (readdir($dh)))
    {
     $i++;
    }
    
    $max = ( ! $this->EE->config->item('max_caches') OR ! is_numeric($this->EE->config->item('max_caches')) OR $this->EE->config->item('max_caches') > 1000) ? 1000 : $this->EE->config->item('max_caches');
    
    if ($i > $max)
    {
     //$this->EE->functions->clear_caching('page');
    }
   }
  }
  
  $this->log_item("URI: ".$this->EE->uri->uri_string);

IF that does not solve the problem? Remove those two slashes and we’ll comment out the whole bit (just for testing- so now it should look like:

// We limit the total number of cache files in order to
  // keep some sanity with large sites or ones that get
  // hit by over-ambitious crawlers.
/*
  if ($this->disable_caching == FALSE)
  {  
   if ($dh = @opendir(APPPATH.'cache/page_cache'))
   {
    $i = 0;
    while (FALSE !== (readdir($dh)))
    {
     $i++;
    }
    
    $max = ( ! $this->EE->config->item('max_caches') OR ! is_numeric($this->EE->config->item('max_caches')) OR $this->EE->config->item('max_caches') > 1000) ? 1000 : $this->EE->config->item('max_caches');
    
    if ($i > $max)
    {
     $this->EE->functions->clear_caching('page');
    }
   }
  }

*/
  
  $this->log_item("URI: ".$this->EE->uri->uri_string);

The /* and */ basically mean ‘comment out everything in between.

Do either of those get the template loading faster? If so- which one?

#11 / Feb 29, 2012 5:15pm

l3training
20 posts

SUCCESS! Can’t believe one commented line of code and we are rockin and rollin’! By commenting out the one line does this affect anything else in the system or in the CP I need to not mess with? Is this because our cache is maxed out or is the cache folder not writeable?

#12 / Feb 29, 2012 5:19pm

l3training

20 posts

All pages on the site are loading under 3-5 sec now. It seems the snippets values are still loading all the snippets code during the template processing. Is that right?

(0.004775 / 4.92MB) Snippets (Keys): freelancer_version|ie6_topbar|snp_footer_legals|snp_footer_copyright|snp_header_logo|snp_footer_js|snp_backtotop|snp_toptab_links|snp_news_mediakit|snp_news_safeharbor|snp_news_l3training|snp_news_l3com|snp_subnav_solutions|snp_subnav_aboutus|snp_subnav_contactus|snp_subnav_gallery|snp_module_requestform|snp_disclaimer_1|snp_subnav_brochures|snp_popup_default|snp_subnav_gallery_support|snp_banner_learnmore|snp_header_droppanel|snp_footer_nav|snp_header_nav|site_id|site_label|site_short_name|last_segment

(0.004825 / 4.94MB) Snippets (Values): FALSE|<!-- IE6 Top Bar --> <div id="ie6-only"> <div class="sub-nav"> <ul> <li><a href="http://www.l-3training.com/central">Employee Portal</a></li> <li><a href="http://www.l-3training.com/forms/request">Request Info</a></li> <li><a href="http://www.l-3training.com/contact">Contact Us</a></li> </ul> </div> </div> <!-- END IE6 Top Bar -->|This material consists of L-3 Communications Corporation general capabilities information that does not contain controlled technical data as defined within the International Traffic in Arms (ITAR) Part 120.10 or Export Administration Regulations (EAR)Part 734.7-11.|<ul> <li>Copyright © 2012 L-3 D.P. Associates, Inc. All rights reserved.
</li> <li><a href="/sitemap/">Sitemap</a></li> <li><a href="/terms-of-use/">Terms of Use</a></li> <li><a href="/privacy-policy/">Privacy Policy</a></li> <li><a href="/forms/feedback/">Feedback</a></li> </ul>|<a href="http://www.l-3training.com" class="logo">/_assets/images/_global/logo_dpa.png</a>| [removed][removed] [removed][removed] [removed][removed] [removed][removed] [removed] if (TTjquery.browser.msie) { TTjquery(window).load(function() {TTjquery('.big-banner #main .main-area').css("padding-top", "118px");});} [removed] [removed] var _gaq = _gaq || []; _gaq.push(['_setAccount', 'UA-23475851-1']); _gaq.push(['_trackPageview']); (function() { var ga = document.createElement('script'); ga.type = 'text/javascript'; ga.async = true; ga.src = ('https:' == document.location.protocol ? 'https://ssl' : 'http://www') + '.google-analytics.com/ga.js'; var s = document.getElementsByTagName('script')[0]; s[removed].insertBefore(ga, s); })(); [removed] [removed]Cufon.now()[removed]|<!-- top link code snippet --> <br class="clear" > <div class="hr_top_link" ></div> <div class="addthis_toolbox addthis_default_style"> <a href="#%22class=%22addthis_button_preferred_1%22&gt&lt/a&gt" class="addthis_button_preferred_1">Back to Top</a> </div> [removed][removed] <!-- end top link code snippet -->|<h1><a href="/">Home</a><a href="/forms/request/">Request Info</a><a href="/support/">Support</a><a href="/contact/">Contact Us</a></h1>|Media and Press Inquiries: Inquiries from media professionals, please contact Jon Evans, Vice President of Operations, 703-664-2958<br> <a href="/index.php/contact/" class="ka_button medium_button medium_cherry" target="" rel="noopener"><span>Contact Us</span></a>|<strong>SAFE HARBOR STATEMENT UNDER THE PRIVATE SECURITIES LITIGATION REFORM ACT OF 1995 </strong> Except for historical information contained herein, the matters set forth in this news release are forward-looking statements. The forward-looking statements set forth above involve a number of risks and uncertainties that could cause actual results to differ materially from any such statement, including the risks and uncertainties discussed in the companyâ��s Safe Harbor Compliance Statement for Forward-looking Statements included in the companyâ��s recent filings, including Forms 10-K and 10-Q, with the Securities and Exchange Commission. The forward-looking statements speak only as of the date made, and the company undertakes no obligation to update these forward-looking statements.|<strong>About {var_sitename}</strong> Headquartered in Alexandria, Virginia, {var_sitename} provides comprehensive and integrated training programs that address training, education, leader development, organizational design and implementation, simulations, democracy transition, and emergency management across a broad spectrum of functional areas. Its customers include the Department of Defense, Department of Justice and select international government agencies. Learn more about {var_sitename} at <a href="http://www.l-3training.com.|">http://www.l-3training.com.|</a><strong>About L-3 Communications</strong> Headquartered in New York City, L-3 Communications employs over 64,000 people worldwide and is a prime contractor in aircraft modernization and maintenance, C3ISR (Command, Control, Communications, Intelligence, Surveillance and Reconnaissance) systems and government services. L-3 is also a leading provider of high technology products, subsystems and systems. The company reported 2007 sales of $14 billion. To learn more about L-3, please visit the companyâ��s web site at <a href="http://www.l-3com.com.|&ltli">http://www.l-3com.com.|<li</a> {if title == "Overview"}class="current_page_item"{/if}><a href="http://{path=/solutions/overview}"><span>Overview</span></a></li> <li {if title == "How It Works"}class="current_page_item"{/if}><a href="{path='/solutions/howitworks'}">

#13 / Mar 01, 2012 10:49am

Robin Sowell
13255 posts

Woot- glad we’ve identified the issue.

The snippets is expected behavior- they’re basically dumped in the globals array for doing a string replace early on. It can be a lot of info- but it makes for a fast replace, so no worries there.

But- identifying the problem isn’t really a solution. We want clearing cache to work. I’m almost surprised you don’t have a slow down when you publish a new entry- most folks have cache set to clear when that happens- in which case it clears all caches- including the page cache. And would thus result in a slow down.

Anyhoo- let’s see what we can do about getting cache to clear properly. If you go to ‘Tools- Data- Clear Caching’- and clear page caches, is it slow? I’d expect it to be. So- that will be a good way to test, while leaving the hack in to avoid your frontend being slow. Clear it a couple of times- make sure it is consistently slow.

ftp in. Go look inside system/expressionengine/cache/page/- any cache files in there? Clear page caches via the CP- refresh FTP- anything happen? Try deleting all of the files inside the cache folder by ftp- can you? Does it fill up again even as you’re deleting them?

I have on rare occasion seen just page caching be slow because so many pages are cached and there’s a high traffic load- and the cache just fills up as fast as it can be emptied. In which case- you want to reduce the pages being cached. So- that could be what’s happening if it seems to be filling up immediately as soon as you try to clear it out via ftp.

The other likely issue is a permission one. If you delete the page_cache folder and recreate it via ftp- and then chmod to 755- let it get a few files in it- then delete the cache via ftp- does that work, and work fast?
#14 / Mar 01, 2012 1:25pm

l3training
20 posts

Clearing Page Cache via CP does take a long time, but when I view the folder via FTP there are over 900 items (folders). Cleared it several times via CP and there is no change in the page_cache directory. Deleting all of the page cache files via FTP now. There is an active .htaccess file in the root of the cache folder. We are on windows though and I have the directory set to read/write only for the local IUSR. Anything else I should do?
#15 / Mar 02, 2012 2:16pm

Dan Decker
7338 posts

Hi l3training,

The cache folder itself needs the equivalent of 777 and the folders inside that need to be the equivalent of 755. I’m not sure what that means in Windows terms.

If you check the permissions via your FTP program, what do they look like?

What are the contents of the .htaccess file?

After clearing the folder via FTP, are you able to clear it using the Control Panel?

Cheers,

Thread

l3training

l3training

Dan Decker

l3training

l3training

l3training

l3training

Robin Sowell

l3training

Robin Sowell

l3training

l3training

Robin Sowell

l3training

Dan Decker

Username

Password

Thread