Debugging template cache / general speed issues

Author Message

steve walker

Wednesday 02 November 2005 5:14:43 am

Hi there,

We seem to be running into some speed issues with 3.6.x builds, and I suspect we're overlooking something pretty basic.

We have template compile and caching all enabled, but the results I'm getting back are:

Time accumulators:
 Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	0.2459 sec	2.6363%	11	0.0224 sec
Mysql Total				
Mysql_queries	0.0289 sec	0.3104%	16	0.0018 sec
Looping result	0.0013 sec	0.0142%	10	0.0001 sec
Template Total	0.5434 sec	5.8%	3	0.1811 sec
Template load	0.1106 sec	1.1856%	3	0.0369 sec
Template processing	0.4317 sec	4.6295%	3	0.1439 sec
override				
Cache load	0.0777 sec	0.8327%	3	0.0259 sec
Total script time:	9.3256 sec	

Pretty horrible :(

In the admin we're seeing >1.5 secs on the template processing.

I've check ini overrides in case there's a setting turning off the caching, but cant find it.

I've been looking at threads like http://ez.no/community/forum/install_configuration/ez_publish_performance and we really should be getting better results.

The machine is a brand spanking new dual P4 (about 3.5 Mhz), loads of RAM. Its running on a windows 2003 server, PHP has something like 128mb memory alloc - and this is the only site running on the box!

Interestingly, we're seeing the same speed problems on development sites we have on our production box (linus based), so I suspect we're overlooking something.

If anyone has some pointers to debug this I'd be very grateful.

Regards, Steve.

http://www.oneworldmarket.co.uk

steve walker

Wednesday 02 November 2005 5:18:18 am

Hi,

Realised that time info wasnt that bad - here's page loads after clearing cache, site has reloaded, and you start visiting other pages:

Time accumulators:
 Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	0.1722 sec	0.6652%	13	0.0132 sec
Mysql Total				
Mysql_queries	3.2601 sec	12.5904%	343	0.0095 sec
Looping result	0.1270 sec	0.4906%	253	0.0005 sec
Template Total	20.1504 sec	77.8%	3	6.7168 sec
Template load	8.4687 sec	32.7060%	3	2.8229 sec
Template parser: create text elements	0.1363 sec	0.5264%	35	0.0039 sec
Template parser: remove whitespace	0.0250 sec	0.0965%	35	0.0007 sec
Template parser: construct tree	0.8069 sec	3.1163%	35	0.0231 sec
Template load and register function	0.0525 sec	0.2027%	6	0.0087 sec
Template processing	11.6806 sec	45.1104%	3	3.8935 sec
override				
Cache load	0.0843 sec	0.3255%	4	0.0211 sec
Sytem overhead				
Fetch class attribute name	0.0000 sec	0.0000%	0	0.0000 sec
class_abstraction				
Instantiating content class attribute	0.0005 sec	0.0020%	6	0.0001 sec
General				
String conversion	0.0081 sec	0.0312%	3	0.0027 sec
String conversion w/ codepage reverse	0.0075 sec	0.0289%	3	0.0025 sec
Total script time:	25.8933 sec	

http://www.oneworldmarket.co.uk

steve walker

Wednesday 02 November 2005 5:21:50 am

This is navigating back to the same page, no cache clearing:

Time accumulators:
 Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	0.1518 sec	4.3682%	12	0.0126 sec
Mysql Total				
Mysql_queries	0.0534 sec	1.5363%	24	0.0022 sec
Looping result	0.0025 sec	0.0712%	17	0.0001 sec
Template Total	1.2465 sec	35.9%	3	0.4155 sec
Template load	0.1060 sec	3.0497%	3	0.0353 sec
Template processing	1.1394 sec	32.7880%	3	0.3798 sec
override				
Cache load	0.0793 sec	2.2830%	4	0.0198 sec
Sytem overhead				
Fetch class attribute name	0.0000 sec	0.0000%	0	0.0000 sec
class_abstraction				
Instantiating content class attribute	0.0005 sec	0.0136%	6	0.0001 sec
General				
String conversion	0.0095 sec	0.2735%	3	0.0032 sec
String conversion w/ codepage reverse	0.0089 sec	0.2550%	3	0.0030 sec
Total script time:	3.4749 sec	

Gets back to the more social, but unacceptable 3.4 secs load time!

Steve

http://www.oneworldmarket.co.uk

steve walker

Thursday 03 November 2005 3:09:06 am

Any ideas??

Thanks, Steve

http://www.oneworldmarket.co.uk

steve walker

Thursday 03 November 2005 9:41:25 am

EzCrew,

Any chance of some input here. We've got cache enabled sites on machines that have plenty of muscle performing terribly.

It looks like the machine always has to chug away when prcessing templates which suggests its not compiling/caching etc, but we dont see how to debug at this point? Its only a problem we seem to have on 3.6.x builds.

Could you give some pointers please?

Thanks, Steve.

http://www.oneworldmarket.co.uk

Ɓukasz Serwatka

Monday 07 November 2005 4:12:57 am

Steve do you have PHP Accelerator installed, on windows eAccelerator works fine.

Personal website -> http://serwatka.net
Blog (about eZ Publish) -> http://serwatka.net/blog

Mark Marsiglio

Monday 07 November 2005 7:31:28 am

Steve- I would also implicate a missing PHP accelerator. I regularly see a 5-10 fold improvement in page load times when using an accelerator. We are using eaccelerator on windows as well, and are getting page loads on pages with complex templates as quick as .25 seconds on a 1.8ghz dual proc. With the accelerator, it was 2.5-3 seconds.

http://www.thinkcreative.com
Turning Ideas Into Strategic Solutions

Powered by eZ Publish™ CMS Open Source Web Content Management. Copyright © 1999-2014 eZ Systems AS (except where otherwise noted). All rights reserved.

eZ debug

Timing: Jan 18 2025 21:06:59
Script start
Timing: Jan 18 2025 21:06:59
Module start 'layout'
Timing: Jan 18 2025 21:06:59
Module start 'content'
Timing: Jan 18 2025 21:07:00
Module end 'content'
Timing: Jan 18 2025 21:07:00
Script end

Main resources:

Total runtime0.6207 sec
Peak memory usage4,096.0000 KB
Database Queries71

Timing points:

CheckpointStart (sec)Duration (sec)Memory at start (KB)Memory used (KB)
Script start 0.00000.0047 588.1641152.6563
Module start 'layout' 0.00480.0022 740.820339.5078
Module start 'content' 0.00700.6123 780.3281630.3906
Module end 'content' 0.61930.0014 1,410.718820.1094
Script end 0.6206  1,430.8281 

Time accumulators:

 Accumulator Duration (sec) Duration (%) Count Average (sec)
Ini load
Load cache0.00290.4689160.0002
Check MTime0.00120.1902160.0001
Mysql Total
Database connection0.00060.093310.0006
Mysqli_queries0.564690.9593710.0080
Looping result0.00090.1470690.0000
Template Total0.595095.920.2975
Template load0.00190.302320.0009
Template processing0.593195.558620.2966
Template load and register function0.00010.024210.0001
states
state_id_array0.00090.146010.0009
state_identifier_array0.00100.165120.0005
Override
Cache load0.00160.2569390.0000
Sytem overhead
Fetch class attribute can translate value0.00060.104130.0002
Fetch class attribute name0.00100.168790.0001
XML
Image XML parsing0.00100.169230.0003
class_abstraction
Instantiating content class attribute0.00000.002090.0000
General
dbfile0.00090.1424230.0000
String conversion0.00000.001040.0000
Note: percentages do not add up to 100% because some accumulators overlap

Templates used to render the page:

UsageRequested templateTemplateTemplate loadedEditOverride
1node/view/full.tplfull/forum_topic.tplextension/sevenx/design/simple/override/templates/full/forum_topic.tplEdit templateOverride template
7content/datatype/view/ezxmltext.tpl<No override>extension/community_design/design/suncana/templates/content/datatype/view/ezxmltext.tplEdit templateOverride template
9content/datatype/view/ezxmltags/paragraph.tpl<No override>extension/ezwebin/design/ezwebin/templates/content/datatype/view/ezxmltags/paragraph.tplEdit templateOverride template
3content/datatype/view/ezxmltags/literal.tpl<No override>extension/community/design/standard/templates/content/datatype/view/ezxmltags/literal.tplEdit templateOverride template
2content/datatype/view/ezimage.tpl<No override>extension/sevenx/design/simple/templates/content/datatype/view/ezimage.tplEdit templateOverride template
1print_pagelayout.tpl<No override>extension/community/design/community/templates/print_pagelayout.tplEdit templateOverride template
 Number of times templates used: 23
 Number of unique templates used: 6

Time used to render debug report: 0.0002 secs