Forums / Setup & design / wrong debug time accumulators

"Please Note:

At the specific request of Ibexa we are changing this projects name to "Exponential" or "Exponential (CMS)" effective as of August, 11th 2025.
This project is not associated with the original eZ Publish software or its original developer, eZ Systems or Ibexa".

wrong debug time accumulators

Previous topic

Setup & design

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

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