Timing

Author Message

Daniel Jüdel

Tuesday 08 December 2009 4:04:33 am

I have some questions to timing. In different installations are different timing differences. Most requests are fast. But some requests have a big difference.

An example:

Module start 'content' 0.0000 sec 0.6597 sec
Module end 'content' 0.6597 sec 0.0543 sec
End 0.7141 sec
Total runtime: 2.6716 sec
....
Total script time: 8.1084 sec

I read the article http://share.ez.no/articles/ez-publish/ez-publish-performance-optimization-part-2-of-3-identifying-trouble-spots-by-debugging. Some important things was written. But I have the following questions:

  1. The difference between "End" and "Total runtime": Is it always a slow connection? Or can be another cause for this difference?
  2. What can be the cause for the difference between "Total runtime" and "Total script time". All other timing points are small (0,0.. seconds). In the example above only "Template processing" (0,6689 seconds) and "Mysql_queries" (0,4184) have not a small time.
  3. In another example the difference between "Module end 'content' " and "End" is sometimes around 0,6 seconds. What can be this cause? In this case a debug-accumulator from first line in pagelayout to the end was 0,13 seconds.

This are examples from different tests. Mostly I have a fast answer with approximately 0,1 seconds. But sometimes I have a slow answer. I don't know why sometimes the timings so different. I hope with your help I can solve the problem.

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 05:22:06
Script start
Timing: Jan 18 2025 05:22:06
Module start 'layout'
Timing: Jan 18 2025 05:22:06
Module start 'content'
Timing: Jan 18 2025 05:22:07
Module end 'content'
Timing: Jan 18 2025 05:22:07
Script end

Main resources:

Total runtime0.7190 sec
Peak memory usage4,096.0000 KB
Database Queries46

Timing points:

CheckpointStart (sec)Duration (sec)Memory at start (KB)Memory used (KB)
Script start 0.00000.0082 587.7891152.6094
Module start 'layout' 0.00820.0035 740.398439.4297
Module start 'content' 0.01180.7058 779.8281408.3281
Module end 'content' 0.71760.0014 1,188.15638.3594
Script end 0.7190  1,196.5156 

Time accumulators:

 Accumulator Duration (sec) Duration (%) Count Average (sec)
Ini load
Load cache0.00360.5007160.0002
Check MTime0.00140.1917160.0001
Mysql Total
Database connection0.00090.127710.0009
Mysqli_queries0.678694.3862460.0148
Looping result0.00040.0561440.0000
Template Total0.683895.120.3419
Template load0.00190.264320.0010
Template processing0.681994.836820.3409
Template load and register function0.00020.024310.0002
states
state_id_array0.00150.202810.0015
state_identifier_array0.00120.170520.0006
Override
Cache load0.00160.2192170.0001
Sytem overhead
Fetch class attribute can translate value0.00070.091510.0007
Fetch class attribute name0.00080.110910.0008
XML
Image XML parsing0.00020.030010.0002
class_abstraction
Instantiating content class attribute0.00000.001110.0000
General
dbfile0.00070.0995100.0001
String conversion0.00000.001540.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
1content/datatype/view/ezxmltext.tpl<No override>extension/community_design/design/suncana/templates/content/datatype/view/ezxmltext.tplEdit templateOverride template
3content/datatype/view/ezxmltags/paragraph.tpl<No override>extension/ezwebin/design/ezwebin/templates/content/datatype/view/ezxmltags/paragraph.tplEdit templateOverride template
1content/datatype/view/ezxmltags/line.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/line.tplEdit templateOverride template
1content/datatype/view/ezxmltags/li.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/li.tplEdit templateOverride template
1content/datatype/view/ezxmltags/ol.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/ol.tplEdit templateOverride template
1print_pagelayout.tpl<No override>extension/community/design/community/templates/print_pagelayout.tplEdit templateOverride template
 Number of times templates used: 9
 Number of unique templates used: 7

Time used to render debug report: 0.0002 secs