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.

eZ debug

Timing: Jan 30 2025 00:50:59
Script start
Timing: Jan 30 2025 00:50:59
Module start 'content'
Timing: Jan 30 2025 00:50:59
Module end 'content'
Timing: Jan 30 2025 00:50:59
Script end

Main resources:

Total runtime0.1843 sec
Peak memory usage2,048.0000 KB
Database Queries141

Timing points:

CheckpointStart (sec)Duration (sec)Memory at start (KB)Memory used (KB)
Script start 0.00000.0058 587.8203180.8516
Module start 'content' 0.00580.0053 768.671993.9141
Module end 'content' 0.01110.1732 862.5859523.7031
Script end 0.1843  1,386.2891 

Time accumulators:

 Accumulator Duration (sec) Duration (%) Count Average (sec)
Ini load
Load cache0.00331.7651200.0002
Check MTime0.00120.6740200.0001
Mysql Total
Database connection0.00060.325110.0006
Mysqli_queries0.137174.37011410.0010
Looping result0.00120.67301390.0000
Template Total0.172793.710.1727
Template load0.00100.536510.0010
Template processing0.171793.159110.1717
Override
Cache load0.00070.371010.0007
Sytem overhead
Fetch class attribute can translate value0.00070.402010.0007
XML
Image XML parsing0.00020.133010.0002
General
dbfile0.00603.2798200.0003
String conversion0.00000.002830.0000
Note: percentages do not add up to 100% because some accumulators overlap

CSS/JS files loaded with "ezjscPacker" during request:

CacheTypePacklevelSourceFiles
CSS0extension/community/design/community/stylesheets/ext/jquery.autocomplete.css
extension/community_design/design/suncana/stylesheets/scrollbars.css
extension/community_design/design/suncana/stylesheets/tabs.css
extension/community_design/design/suncana/stylesheets/roadmap.css
extension/community_design/design/suncana/stylesheets/content.css
extension/community_design/design/suncana/stylesheets/star-rating.css
extension/community_design/design/suncana/stylesheets/syntax_and_custom_tags.css
extension/community_design/design/suncana/stylesheets/buttons.css
extension/community_design/design/suncana/stylesheets/tweetbox.css
extension/community_design/design/suncana/stylesheets/jquery.fancybox-1.3.4.css
extension/bcsmoothgallery/design/standard/stylesheets/magnific-popup.css
extension/sevenx/design/simple/stylesheets/star_rating.css
extension/sevenx/design/simple/stylesheets/libs/fontawesome/css/all.min.css
extension/sevenx/design/simple/stylesheets/main.v02.css
extension/sevenx/design/simple/stylesheets/main.v02.res.css
JS0extension/ezjscore/design/standard/lib/yui/3.17.2/build/yui/yui-min.js
extension/ezjscore/design/standard/javascript/jquery-3.7.0.min.js
extension/community_design/design/suncana/javascript/jquery.ui.core.min.js
extension/community_design/design/suncana/javascript/jquery.ui.widget.min.js
extension/community_design/design/suncana/javascript/jquery.easing.1.3.js
extension/community_design/design/suncana/javascript/jquery.ui.tabs.js
extension/community_design/design/suncana/javascript/jquery.hoverIntent.min.js
extension/community_design/design/suncana/javascript/jquery.popmenu.js
extension/community_design/design/suncana/javascript/jScrollPane.js
extension/community_design/design/suncana/javascript/jquery.mousewheel.js
extension/community_design/design/suncana/javascript/jquery.cycle.all.js
extension/sevenx/design/simple/javascript/jquery.scrollTo.js
extension/community_design/design/suncana/javascript/jquery.cookie.js
extension/community_design/design/suncana/javascript/ezstarrating_jquery.js
extension/community_design/design/suncana/javascript/jquery.initboxes.js
extension/community_design/design/suncana/javascript/app.js
extension/community_design/design/suncana/javascript/twitterwidget.js
extension/community_design/design/suncana/javascript/community.js
extension/community_design/design/suncana/javascript/roadmap.js
extension/community_design/design/suncana/javascript/ez.js
extension/community_design/design/suncana/javascript/ezshareevents.js
extension/sevenx/design/simple/javascript/main.js

Templates used to render the page:

UsageRequested templateTemplateTemplate loadedEditOverride
1pagelayout.tpl<No override>extension/sevenx/design/simple/templates/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