CGSmartImage very slow after update to 1.16 [SOLVED]

[rotezecke]

I run 1.11.10 on debian, 3.2.0-4-amd64, php 5.4.4-14+deb7u8, MySQL 5.5.35-0+wheezy1
updated the recent release of the CG modules, after which the site became very 'sluggish' - page loads from 5 - 20 seconds (on 127.0.0.1 !).
so i installed my backup and tested after each updated module update. CGSmartImage triggers it. Debug info that seems relevant:

...
Debug: (0.341421) - (usage: 17411184) - (peak: 17546592)

Loading /var/www/cmsms/modules/CGExtensions/lib/class.cge_http.php = 13880 bytes for an approximate total of 4544824

Debug: (6.027257) - (usage: 17627336) - (peak: 17749288)

Loading /var/www/cmsms/modules/CGSmartImage/lib/class.CGImageBase.php = 48064 bytes for an approximate total of 4592888

Debug display of 'Fetch globalcontent:floatingImage end':(6.055467) - (usage: 17620040) - (peak: 18033008)
Debug display of 'Fetch globalcontent:floatingImage start':(6.057037) - (usage: 17604776) - (peak: 18033008)
Debug display of 'Fetch globalcontent:floatingImage end':(6.712123) - (usage: 17624432) - (peak: 18088416)
Debug display of 'Fetch globalcontent:floatingImage start':(6.715725) - (usage: 17640448) - (peak: 18088416)
Debug display of 'Fetch globalcontent:floatingImage end':(7.386482) - (usage: 17674320) - (peak: 18121568)
Debug display of 'Fetch globalcontent:floatingImage start':(7.390378) - (usage: 17671344) - (peak: 18121568)
Debug display of 'Fetch globalcontent:floatingImage end':(8.055845) - (usage: 17732632) - (peak: 18152880)
Debug display of 'Fetch globalcontent:floatingImage start':(8.05946) - (usage: 17734352) - (peak: 18152880)
Debug display of 'Fetch globalcontent:floatingImage end':(8.721538) - (usage: 17766728) - (peak: 18216664)
Debug display of 'Fetch globalcontent:floatingImage start':(8.725107) - (usage: 17761408) - (peak: 18216664)
Debug display of 'Fetch globalcontent:floatingImage end':(9.632014) - (usage: 17814136) - (peak: 18244592)
Debug display of 'Fetch globalcontent:floatingImage start':(9.636018) - (usage: 17819296) - (peak: 18244592)
Debug display of 'Fetch globalcontent:floatingImage end':(10.305406) - (usage: 17849224) - (peak: 18303112)
Debug display of 'Fetch globalcontent:floatingImage start':(10.309051) - (usage: 17845640) - (peak: 18303112)
Debug display of 'Fetch globalcontent:floatingImage end':(10.980526) - (usage: 17884936) - (peak: 18329560)
Debug display of 'Fetch globalcontent:floatingImage start':(10.98704) - (usage: 17900680) - (peak: 18329560)
Debug display of 'Fetch globalcontent:floatingImage end':(11.680761) - (usage: 17955632) - (peak: 18385912)
Debug display of 'Fetch module_db_tpl:CGBlog;summarysimple-summary end':(11.682994) - (usage: 17807136) - (peak: 18385912)
Debug: (11.683171) - (usage: 17790152) - (peak: 18385912)

End CGBlog summary view

Debug display of 'Fetch content:content_en end':(11.683677) - (usage: 17613312) - (peak: 18385912)
Debug display of 'Fetch content:pre_menu start':(11.683896) - (usage: 17613032) - (peak: 18385912)
Debug display of 'Fetch content:pre_menu end':(11.694685) - (usage: 17639608) - (peak: 18385912)
Debug display of 'Fetch content:smallDiv start':(11.694763) - (usage: 17639224) - (peak: 18385912)
Debug: (11.698569) - (usage: 17715528) - (peak: 18385912)

(mysql): SELECT a.*,count(b.blog_id) as count
FROM rpc2cms_module_cgblog_categories a
LEFT JOIN rpc2cms_module_cgblog_blog_categories b
ON a.id = b.category_id
LEFT JOIN rpc2cms_module_cgblog c
ON c.cgblog_id = b.blog_id WHERE c.status = 'published' AND COALESCE(c.end_time,NOW()) >= NOW() GROUP BY a.id ORDER BY sort_order

Debug display of 'Fetch module_db_tpl:CGBlog;browsecatsimpleTabs start':(11.70506) - (usage: 17826704) - (peak: 18385912)
Debug display of 'CMSModuleDbTemplateResource startCGBlog;browsecatsimpleTabs':(11.705244) - (usage: 17830264) - (peak: 18385912)
...

{* skip to last line - only slight delay from rather large menu calls *}
...
Debug: (12.260583) - (usage: 28678240) - (peak: 29173032)
Requested deactivated module FrontEndUsers

While the delays seem to be caused mostly by Global Content Blocks (and some UDTs), all of these contain a call to CGSmartImage.

here's the juicy bit of the GCB:

Code: Select all

 {capture assign='floatImgSized'}
  {CGSmartImage src=$gcb_params['src'] alt=$gcb_params['alt'] title=$gcb_params['title'] alias=$gcb_params['size'] noembed=1}
 {/capture}

where the alias would convert to:

filter_roundedcorners=5 filter_resize='w,189,0' quality=85

or similar.
out of curiosity i tried:
assign='floatImgSized' instead of capture (insignificantly faster, maybe), and
removed the filter_roundedcorners=5 from the alias lines.
Still the fastest I get is 6 seconds (~ 0.7 seconds per GCB), and the worst was 28 seconds, but mostly caused by CGImageBase.php if I read this correctly:

...
Debug: (0.309619) - (usage: 17386304) - (peak: 17521904)

Loading /var/www/cmsms/modules/CGExtensions/lib/class.cge_http.php = 13848 bytes for an approximate total of 4521408

Debug: (27.818493) - (usage: 17602392) - (peak: 17724544)

Loading /var/www/cmsms/modules/CGSmartImage/lib/class.CGImageBase.php = 48032 bytes for an approximate total of 4569440
...

There's nothing in PHP error logs. Any idea, or anyone else with this problem? And thank you for reading this post.

Edit:
here's the same debug info with CGSmartImage 1.15

...
Debug: (0.328001) - (usage: 17175976) - (peak: 17325640)

Loading /var/www/cmsms/modules/CGExtensions/lib/class.cge_browser.php = 323976 bytes for an approximate total of 4407064

Debug display of 'Fetch globalcontent:floatingImage end':(0.329259) - (usage: 17128712) - (peak: 17637360)
Debug display of 'Fetch globalcontent:floatingImage start':(0.330502) - (usage: 17130968) - (peak: 17637360)
Debug display of 'Fetch globalcontent:floatingImage end':(0.33204) - (usage: 17165224) - (peak: 17660904)
Debug display of 'Fetch globalcontent:floatingImage start':(0.333239) - (usage: 17162376) - (peak: 17660904)
Debug display of 'Fetch globalcontent:floatingImage end':(0.33475) - (usage: 17223664) - (peak: 17684064)
Debug display of 'Fetch globalcontent:floatingImage start':(0.335924) - (usage: 17225400) - (peak: 17684064)
Debug display of 'Fetch globalcontent:floatingImage end':(0.337634) - (usage: 17257784) - (peak: 17740336)
Debug display of 'Fetch globalcontent:floatingImage start':(0.338922) - (usage: 17268848) - (peak: 17740336)
Debug display of 'Fetch globalcontent:floatingImage end':(0.340516) - (usage: 17321576) - (peak: 17778176)
Debug display of 'Fetch globalcontent:floatingImage start':(0.341746) - (usage: 17310096) - (peak: 17778176)
Debug display of 'Fetch globalcontent:floatingImage end':(0.34322) - (usage: 17340024) - (peak: 17812256)
Debug display of 'Fetch globalcontent:floatingImage start':(0.344445) - (usage: 17353080) - (peak: 17812256)
Debug display of 'Fetch globalcontent:floatingImage end':(0.345882) - (usage: 17392312) - (peak: 17848704)
Debug display of 'Fetch globalcontent:floatingImage start':(0.347564) - (usage: 17391672) - (peak: 17848704)
Debug display of 'Fetch globalcontent:floatingImage end':(0.349058) - (usage: 17446688) - (peak: 17887080)
Debug display of 'Fetch globalcontent:floatingImage start':(0.350268) - (usage: 17450352) - (peak: 17887080)
Debug display of 'Fetch globalcontent:floatingImage end':(0.351724) - (usage: 17470184) - (peak: 17945040)
Debug display of 'Fetch module_db_tpl:CGBlog;summarysimple-summary end':(0.352562) - (usage: 17319592) - (peak: 17945040)
Debug display of 'Fetch content:content_en end':(0.352717) - (usage: 17167520) - (peak: 17945040)
Debug display of 'Fetch content:pre_menu start':(0.35279) - (usage: 17167240) - (peak: 17945040)
Debug display of 'Fetch content:pre_menu end':(0.358529) - (usage: 17193816) - (peak: 17945040)
Debug display of 'Fetch content:smallDiv start':(0.358606) - (usage: 17193432) - (peak: 17945040)
Debug: (0.362433) - (usage: 17262152) - (peak: 17945040)

(mysql): SELECT a.*,count(b.blog_id) as count
FROM rpc2cms_module_cgblog_categories a
LEFT JOIN rpc2cms_module_cgblog_blog_categories b
ON a.id = b.category_id
LEFT JOIN rpc2cms_module_cgblog c
ON c.cgblog_id = b.blog_id
WHERE c.status = 'published' AND (( IFNULL(end_time, '1970-01-01 01:00:01') = '1970-01-01 01:00:01') OR (end_time > '2014-04-11 05:16:13')) GROUP BY a.id
ORDER BY sort_order

Debug display of 'Fetch module_db_tpl:CGBlog;browsecatsimpleTabs start':(0.368726) - (usage: 17375976) - (peak: 17945040)
Debug display of 'CMSModuleDbTemplateResource startCGBlog;browsecatsimpleTabs':(0.368894) - (usage: 17379488) - (peak: 17945040)
...

----------------------------------------------

Cms Version: 1.11.10

Installed Modules:

CMSMailer: 5.2.2
MenuManager: 1.8.6
ModuleManager: 1.5.5
News: 2.14.2
CGSmartImage: 1.16
Search: 1.7.11
TinyMCE: 2.9.12
CGSimpleSmarty: 1.7.2
CGExtensions: 1.38.6
CGBlog: 1.11.6
CGFeedback: 1.6.2
Captcha: 0.4.6
FormBuilder: 0.7.3
Showtime: 3.3
GBFilePicker: 1.3.3
JQueryTools: 1.2.6


Config Information:

php_memory_limit:
process_whole_template:
max_upload_size: 2000000
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.4.4-14+deb7u8
md5_function: On (True)
gd_version: 2
tempnam_function: On (True)
magic_quotes_runtime: Off (False)
E_STRICT: 2048
E_DEPRECATED: 8192
memory_limit: 128M
max_execution_time: 30
output_buffering: 4096
safe_mode: Off (False)
file_uploads: On (True)
post_max_size: 8M
upload_max_filesize: 2M
session_save_path: /tmp (1777)
session_use_cookies: On (True)
xml_function: On (True)
xmlreader_class: On (True)


Server Information:

Server Api: apache2handler
Server Db Type: MySQL (mysql)
Server Db Version: 5.5.35
Server Db Grants: Found a "GRANT ALL" statement that appears to be suitable
Server Time Diff: No filesystem time difference found


----------------------------------------------

[Rolf]

{CGSmartImage ....params.... assign='floatImgSized'} is much faster

[velden]

Code: Select all

{capture assign='floatImgSized'}
  {CGSmartImage src=$gcb_params['src'] alt=$gcb_params['alt'] title=$gcb_params['title'] alias=$gcb_params['size'] noembed=1}
 {/capture}

Would $gcb_params['src'] be a http url? Could cause CGSI to download image via http (under certain conditions) and that may be slow(er)

[rotezecke]

Yes, in case of the page I used for debug info i posted, the $gcb_params['src'] comes from: {$entry->file_location}/{$field->value} which is in fact a http URL. (i tested on CGBlog summary page with {$entry->file_location} which is broken in latest CGBlog but I fixed that following suggestion in bug report).
However, pages outside CGBlog loaded equally slow, and i know most of them would have $gcb_params['src'] ="/uploads/..." or $gcb_params['src'] ="uploads/..."
even if everything was http, does this explain why CGSI 1.15 loads the same page (with 9 images) in half a second, and CGSI 1.16 takes a minimum of 6sec? i've been using this GCB for some time now (nearly 2 years).

@Rolf, i tried assign over capture but that aint it.

[Stikki]

There is something wrong with device detecting service that Calguy uses. Service causes delay on load and even it should cache it, it seems not to.

Disable: Enable Responsive Images

Solves problem.

[rotezecke]

That's it! Thanks.