wrong debug time accumulators

Next topic

Author	Message
Marko Žmak	Monday 23 January 2006 3:14:20 pm I've been doing some optimizations on my site, so I started examining eZ timing points. I found out that the time accumulators displayed on the bottom are not consistent. Total execution time doesn't seem to be the sum of all acumulators. Why? Here's the ouptut: Timing points: Checkpoint Elapsed Rel. Elapsed Memory Rel. Memory Module start 'content' 0.0000 sec 0.0721 sec 0.0000KB 0.0000KB Module end 'content' 0.0721 sec 0.8162 sec 0.0000KB 0.0000KB End 0.8883 sec 0.0000KB 0.0000KB Total runtime: 3.3168 sec Time accumulators: Accumulator Elapsed Percent Count Average ini_load Load cache 0.0328 sec 0.8468% 11 0.0030 sec FindInputFiles 0.0192 sec 0.4947% 11 0.0017 sec Mysql Total Mysql_queries 0.0151 sec 0.3898% 32 0.0005 sec Looping result 0.0141 sec 0.3643% 31 0.0005 sec TS translator TS init 0.0169 sec 0.4361% 4 0.0042 sec TS cache load 0.0099 sec 0.2547% 4 0.0025 sec TS context load 0.0072 sec 0.1848% 4 0.0018 sec Template Total 0.8794 sec 22.7% 2 0.4397 sec Template load 0.0216 sec 0.5571% 2 0.0108 sec Template processing 0.8571 sec 22.1066% 2 0.4285 sec Template load and register function 0.0049 sec 0.1265% 3 0.0016 sec override Cache load 0.0176 sec 0.4532% 3 0.0059 sec XML Image XML parsing 0.0093 sec 0.2396% 3 0.0031 sec Sytem overhead Fetch class attribute name 0.0018 sec 0.0466% 1 0.0018 sec class_abstraction Instantiating content class attribute 0.0027 sec 0.0705% 1 0.0027 sec Total script time: 3.8771 sec Acourding to whis, Total time should be 1,9 sec, bu it's 3,8. How come? Where's the missing time? -- Nothing is impossible. Not if you can imagine it! Hubert Farnsworth
Mark Marsiglio	Monday 13 February 2006 10:49:54 pm I notice this issue as well. I am running a site that, when cached, will load anywhere from .20 to .80 seconds. When it is at .20, the accumulators add up to the right amount of seconds, and equal 100%. When at .80 seconds total, the accumulators still add up to .20, and they total only about 25%. It would appear that some loads are seeing some phantom time loss. I am running ez on some other servers that do not seem to experience this problem. They are actually slower servers, but render pages in as little as .08 seconds. In all cases, the servers are running a PHP Acccelerator. In the most recent case the hardware is a 8-core Xeon server with 4gb RAM, so the processing horsepower seems like it should render the page a little better. http://www.thinkcreative.com Turning Ideas Into Strategic Solutions

Author

Message

Monday 23 January 2006 3:14:20 pm

I've been doing some optimizations on my site, so I started examining eZ timing points. I found out that the time accumulators displayed on the bottom are not consistent. Total execution time doesn't seem to be the sum of all acumulators. Why? Here's the ouptut:

Timing points:
Checkpoint Elapsed Rel. Elapsed Memory Rel. Memory
Module start 'content' 0.0000 sec 0.0721 sec 0.0000KB 0.0000KB
Module end 'content' 0.0721 sec 0.8162 sec 0.0000KB 0.0000KB
End 0.8883 sec 0.0000KB 0.0000KB
Total runtime: 3.3168 sec
Time accumulators:
Accumulator Elapsed Percent Count Average
ini_load
Load cache 0.0328 sec 0.8468% 11 0.0030 sec
FindInputFiles 0.0192 sec 0.4947% 11 0.0017 sec
Mysql Total
Mysql_queries 0.0151 sec 0.3898% 32 0.0005 sec
Looping result 0.0141 sec 0.3643% 31 0.0005 sec
TS translator
TS init 0.0169 sec 0.4361% 4 0.0042 sec
TS cache load 0.0099 sec 0.2547% 4 0.0025 sec
TS context load 0.0072 sec 0.1848% 4 0.0018 sec
Template Total 0.8794 sec 22.7% 2 0.4397 sec
Template load 0.0216 sec 0.5571% 2 0.0108 sec
Template processing 0.8571 sec 22.1066% 2 0.4285 sec
Template load and register function 0.0049 sec 0.1265% 3 0.0016 sec
override
Cache load 0.0176 sec 0.4532% 3 0.0059 sec
XML
Image XML parsing 0.0093 sec 0.2396% 3 0.0031 sec
Sytem overhead
Fetch class attribute name 0.0018 sec 0.0466% 1 0.0018 sec
class_abstraction
Instantiating content class attribute 0.0027 sec 0.0705% 1 0.0027 sec
Total script time: 3.8771 sec

Acourding to whis, Total time should be 1,9 sec, bu it's 3,8. How come? Where's the missing time?

--
Nothing is impossible. Not if you can imagine it!

Hubert Farnsworth

Mark Marsiglio

Monday 13 February 2006 10:49:54 pm

I notice this issue as well. I am running a site that, when cached, will load anywhere from .20 to .80 seconds. When it is at .20, the accumulators add up to the right amount of seconds, and equal 100%.

When at .80 seconds total, the accumulators still add up to .20, and they total only about 25%. It would appear that some loads are seeing some phantom time loss.

I am running ez on some other servers that do not seem to experience this problem. They are actually slower servers, but render pages in as little as .08 seconds.

In all cases, the servers are running a PHP Acccelerator. In the most recent case the hardware is a 8-core Xeon server with 4gb RAM, so the processing horsepower seems like it should render the page a little better.

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

eZ debug

Timing:	Jan 19 2025 01:01:00
Script start
Timing:	Jan 19 2025 01:01:00
Module start 'layout'
Timing:	Jan 19 2025 01:01:00
Module start 'content'
Timing:	Jan 19 2025 01:01:01
Module end 'content'
Timing:	Jan 19 2025 01:01:01
Script end

Main resources:

Total runtime	0.7451 sec
Peak memory usage	4,096.0000 KB
Database Queries	54

Timing points:

Checkpoint	Start (sec)	Duration (sec)	Memory at start (KB)	Memory used (KB)
Script start	0.0000	0.0089	590.2891	152.6250
Module start 'layout'	0.0089	0.0039	742.9141	39.4453
Module start 'content'	0.0128	0.7308	782.3594	545.2969
Module end 'content'	0.7436	0.0014	1,327.6563	12.1641
Script end	0.7450		1,339.8203

Time accumulators:

Accumulator	Duration (sec)	Duration (%)	Count	Average (sec)
Ini load
Load cache	0.0035	0.4709	16	0.0002
Check MTime	0.0014	0.1889	16	0.0001
Mysql Total
Database connection	0.0005	0.0699	1	0.0005
Mysqli_queries	0.6850	91.9406	54	0.0127
Looping result	0.0006	0.0803	52	0.0000
Template Total	0.7045	94.5	2	0.3522
Template load	0.0027	0.3608	2	0.0013
Template processing	0.7017	94.1835	2	0.3509
Template load and register function	0.0001	0.0152	1	0.0001
states
state_id_array	0.0015	0.2016	1	0.0015
state_identifier_array	0.0008	0.1056	2	0.0004
Override
Cache load	0.0022	0.2929	43	0.0001
Sytem overhead
Fetch class attribute can translate value	0.0012	0.1578	2	0.0006
Fetch class attribute name	0.0018	0.2359	4	0.0004
XML
Image XML parsing	0.0014	0.1884	2	0.0007
class_abstraction
Instantiating content class attribute	0.0000	0.0012	4	0.0000
General
dbfile	0.0010	0.1314	23	0.0000
String conversion	0.0000	0.0012	4	0.0000
Note: percentages do not add up to 100% because some accumulators overlap

Templates used to render the page:

Usage	Requested template	Template	Template loaded
1	node/view/full.tpl	full/forum_topic.tpl	extension/sevenx/design/simple/override/templates/full/forum_topic.tpl
2	content/datatype/view/ezimage.tpl	<No override>	extension/sevenx/design/simple/templates/content/datatype/view/ezimage.tpl
2	content/datatype/view/ezxmltext.tpl	<No override>	extension/community_design/design/suncana/templates/content/datatype/view/ezxmltext.tpl
3	content/datatype/view/ezxmltags/paragraph.tpl	<No override>	extension/ezwebin/design/ezwebin/templates/content/datatype/view/ezxmltags/paragraph.tpl
1	content/datatype/view/ezxmltags/line.tpl	<No override>	design/standard/templates/content/datatype/view/ezxmltags/line.tpl
1	print_pagelayout.tpl	<No override>	extension/community/design/community/templates/print_pagelayout.tpl
Number of times templates used: 10 Number of unique templates used: 6

Time used to render debug report: 0.0001 secs