Performance: Template load - what is it?

Author Message

Piotrek Karaś

Thursday 28 February 2008 6:34:17 am

Hi,

I'd be grateful if someone experienced could take a minute and explain:

1) What is the <b>Template load</b> element in the debug information?
2) What could be the reason that two of <b>it</b> take <b>so much time</b>?

Some context information below:

Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	0.4236 sec	1.5866%	14	0.0303 sec
FindInputFiles	0.3311 sec	1.2402%	14	0.0236 sec
Mysql Total				
Mysql_queries	0.0107 sec	0.0402%	5	0.0021 sec
Looping result	0.0002 sec	0.0008%	5	0.0000 sec
TS translator				
TS init	0.0574 sec	0.2149%	9	0.0064 sec
TS cache load	0.0105 sec	0.0393%	9	0.0012 sec
TS context load	0.0089 sec	0.0334%	9	0.0010 sec
Template Total	25.9305 sec	97.1%	2	12.9652 sec
Template load	25.8541 sec	96.8511%	2	12.9271 sec
String conversion in template resource	0.0003 sec	0.0011%	1	0.0003 sec
Template parser: create text elements	0.0189 sec	0.0710%	1	0.0189 sec
Template parser: remove whitespace	0.0013 sec	0.0048%	1	0.0013 sec
Template parser: construct tree	0.1124 sec	0.4209%	1	0.1124 sec
Template load and register function	0.0227 sec	0.0852%	9	0.0025 sec
Template processing	0.0762 sec	0.2854%	2	0.0381 sec
override				
Cache load	0.0960 sec	0.3597%	2	0.0480 sec
General				
String conversion	0.0003 sec	0.0010%	3	0.0001 sec
dbfile	0.0010 sec	0.0036%	4	0.0002 sec
String conversion w/ mbstring	0.0002 sec	0.0009%	1	0.0002 sec
Total script time:	26.6947 sec

Thanks!!!

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

André R.

Thursday 28 February 2008 3:27:19 pm

Is this straight after a template cache clear or is template compilation disabled?

eZ Online Editor 5: http://projects.ez.no/ezoe || eZJSCore (Ajax): http://projects.ez.no/ezjscore || eZ Publish EE http://ez.no/eZPublish/eZ-Publish-Enterprise-Subscription
@: http://twitter.com/andrerom

Piotrek Karaś

Thursday 28 February 2008 3:50:50 pm

Neither ;) This is a site with an average of 200-300 queries per page (when cache has been cleared), look at the query count, it's 5, it's all cached. And the template compilation was not disabled ;)

Normally a page of that site takes 0.2s to generate on that server, today - without any changes made - it went to 20-40 seconds, and it was consistent over about 2 hours to show over 95% of resources used for this part. Then it went back to normal. I suspect something might be wrong with the server (it's a VPS), but I have no idea what to have checked by the provider ;(

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

Piotrek Karaś

Wednesday 05 March 2008 5:06:22 am

Same thing is happening again... ;( Any thoughts?

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

Piotrek Karaś

Wednesday 19 March 2008 12:37:54 am

And again... only now this was 130sek... this really looks bad...

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

André R.

Wednesday 19 March 2008 1:32:54 am

I'm afraid I haven't seen this before. You should report it in the issue tracker, but it would help if it is reproducible somehow of course... :/

One thing from Kristof though: Check file permission on the cache files, if they suddenly change so the web server can't read it, that might explain it.

eZ Online Editor 5: http://projects.ez.no/ezoe || eZJSCore (Ajax): http://projects.ez.no/ezjscore || eZ Publish EE http://ez.no/eZPublish/eZ-Publish-Enterprise-Subscription
@: http://twitter.com/andrerom

Piotrek Karaś

Wednesday 19 March 2008 5:44:08 am

Hi André,

<i>I'm afraid I haven't seen this before. You should report it in the issue tracker, but it would help if it is reproducible somehow of course... :/</i>
Looking for some consistency myself, but this simply happens, and then some minutes later is gone...

<i>One thing from Kristof though: Check file permission on the cache files, if they suddenly change so the web server can't read it, that might explain it.</i>
Thanks. I'll give those a closer look. However - in all problems that I have experienced with permissions on different servers (can't read, can't write etc...), it has never taken that long... just like with pure PHP - file access errors take some additional time, but we're not talking minutes, right? ;)

Let you know if I discover something new...

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

Xavier Dutoit

Monday 24 March 2008 11:59:36 pm

Hi,

run top on the server when it goes nuts, you might see something.

It reminds me a problem I had: the cache for the images was cleared, and it was regenerating all the images, I had enough image galleries to put the server on its knees (and I suspect it happily generates the same thumbnail several times for each request if two access simultaneously).

X+

http://www.sydesy.com

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 19 2025 01:20:02
Script start
Timing: Jan 19 2025 01:20:02
Module start 'layout'
Timing: Jan 19 2025 01:20:02
Module start 'content'
Timing: Jan 19 2025 01:20:02
Module end 'content'
Timing: Jan 19 2025 01:20:02
Script end

Main resources:

Total runtime0.0144 sec
Peak memory usage2,048.0000 KB
Database Queries3

Timing points:

CheckpointStart (sec)Duration (sec)Memory at start (KB)Memory used (KB)
Script start 0.00000.0054 589.1797152.6250
Module start 'layout' 0.00540.0032 741.804739.4453
Module start 'content' 0.00860.0042 781.2500105.4922
Module end 'content' 0.01280.0016 886.742246.3047
Script end 0.0144  933.0469 

Time accumulators:

 Accumulator Duration (sec) Duration (%) Count Average (sec)
Ini load
Load cache0.002114.8023140.0002
Check MTime0.00106.7137140.0001
Mysql Total
Database connection0.00085.335510.0008
Mysqli_queries0.002819.279830.0009
Looping result0.00000.173910.0000
Template Total0.00139.010.0013
Template load0.00074.961210.0007
Template processing0.00064.002110.0006
Override
Cache load0.00043.049610.0004
General
dbfile0.00021.729480.0000
String conversion0.00000.071240.0000
Note: percentages do not add up to 100% because some accumulators overlap

Templates used to render the page:

UsageRequested templateTemplateTemplate loadedEditOverride
1print_pagelayout.tpl<No override>extension/community/design/community/templates/print_pagelayout.tplEdit templateOverride template
 Number of times templates used: 1
 Number of unique templates used: 1

Time used to render debug report: 0.0001 secs