[solved]CMSMS 1.11.8 performance regression [w/loadprops=1]

[fredp]

Note: Calguy100 pointed out that this issue is only triggered when loadprops is true. If loadprops=0 is used, e.g. {menu loadprops=0...}, then there is NO performance regression!

After upgraded a large site (~850 pages) from CMSMS 1.11.7 to 1.11.8, I see a significant performance regression when viewing my site-map.html page. This page uses a Menu Manager call to display a site-map for humans.

With CMSMS 1.11.7, after optimizing tables then clearing the CMSMS and browser caches, the site-map.html page is fully rendered in a little over 3 seconds. Here are the 'site_performance_info' stats for the page:

Code: Select all

Debug: (3.311462) - (usage: 45752720) - (peak: 46463280)

3.311285 / 719 / 45006568 / 46463280

But after upgrading to CMSMS 1.11.8, the same page fails to render, leaving the following error(s) in the error_log (I tried to view the page three times in a row):

Code: Select all

[10-Sep-2013 02:52:56 America/Chicago] PHP Fatal error:  Maximum execution time of 31 seconds exceeded in /home/username/public_html/lib/classes/class.contentoperations.inc.php on line 780
[10-Sep-2013 02:53:46 America/Chicago] PHP Fatal error:  Maximum execution time of 31 seconds exceeded in /home/username/public_html/lib/classes/class.contentoperations.inc.php on line 779
[10-Sep-2013 03:01:24 America/Chicago] PHP Fatal error:  Maximum execution time of 31 seconds exceeded in /home/username/public_html/lib/classes/class.contentoperations.inc.php on line 780

Here's the page content:

Code: Select all

{menu template="minimal_sitemap" nocache}

Here's the System Information:

Cms Version: 1.11.8

Installed Modules:

CMSMailer: 5.2.1
CMSPrinting: 1.0.5
FileManager: 1.4.3
MenuManager: 1.8.6
ModuleManager: 1.5.5
News: 2.13
Search: 1.7.10
TinyMCE: 2.9.12
Gallery: 1.6.1
FormBuilder: 0.7.4
fp_visit_stats: 1.0
fp_email_utils: 1.0
fp_img_utils: 1.0
fp_tim: 1.1.1
MicroTiny: 1.2.5
ThemeManager: 1.1.8


Config Information:

php_memory_limit:
process_whole_template:
max_upload_size: 64000000
url_rewriting: mod_rewrite
page_extension: .html
query_var: page
image_manipulation_prog: GD
auto_alias_content: true
locale:
default_encoding: utf-8
admin_encoding: utf-8
set_names: true


Php Information:

phpversion: 5.3.27
md5_function: On (True)
gd_version: 2
tempnam_function: On (True)
magic_quotes_runtime: Off (False)
E_STRICT: 0
E_DEPRECATED: 0
memory_limit: 256M
max_execution_time: 31
output_buffering: On
safe_mode: Off (False)
file_uploads: On (True)
post_max_size: 64M
upload_max_filesize: 64M
session_save_path: /home/username/sessions (0700)
session_use_cookies: On (True)
xml_function: On (True)
xmlreader_class: On (True)


Server Information:

Server Api: cgi-fcgi
Server Db Type: MySQL (mysqli)
Server Db Version: 5.5.30
Server Db Grants: Found a "GRANT ALL" statement that appears to be suitable
Server Time Diff: No filesystem time difference found

Performance was restored after reverting back to CMSMS 1.11.7.

Hope this helps. Let me know if you need further info.
---fredp

P.S. Thanks again for all your efforts, Dev. Team!

[fredp]

Just adding a bit more information...

To be sure there wasn't a server issue in the above case, I made two copies of the same 1.11.7 site on my laptop and upgraded one to 1.11.8. Then, I compared times to render my MenuManager driven site-map.html page, after clearing the CMSMS and browser caches:

The good news is that 1.11.8 didn't get the timeout; it displayed the complete page!
The bad news is that 1.11.8 was 11 times slower than 1.11.7, at least for this page.

1.375107 / 719 / 44994480 / 46354696

15.308511 / 36 / 56930312 / 78910504

While 1.11.8 used 70% more memory, it used just 5% of the db queries! That's a significant reduction in db calls, which, I agree should have been a performance win.

I'll try to investigate this further...

[fredp]

I found the cause, then submit a bug report (#9549) and a potential fix.

[fredp]

Calguy100 pointed out that this issue is only triggered when loadprops is true. This made me realize that my loadprops=0 parameter had inadvertently been removed from my {menu ...} call months ago. The good news is, once I added it back, performance was restored on CMSMS 1.11.8!

{menu template="minimal_sitemap" loadprops=0 nocache}

Thanks again to the dev team for all their efforts.

[fredp]

After upgrading to CMSMS 1.11.9, the original problem was resolved.

Thanks again for the fix.