eZ Publish Performance Optimization Part 2 of 3: Identifying Trouble Spots by Debugging

This article is the second in a three-part series on eZ Publish performance. The first article introduced basic performance terminology and discussed tools to benchmark your site's performance. This article will outline the eZ Publish debug output features.

The third and final article will provide practical solutions for optimizing performance.

If your actual performance (from your benchmarking tests) does not meet your requirements, you should finetune your eZ Publish installation. Recall the different components of page load time, such as page generation and transfer time. Here, we will take a look at how you can identify the causes of slow website performance, focusing on eZ Publish settings that affect page generation times.

Debug output

Debug output is a built-in mechanism in eZ Publish that provides detailed information for troubleshooting. Debug output provides valuable information about timings, SQL queries, template processing and more. You can enable debug output from within the Administration Interface (in the Common INI settings in the Setup tab) or by adding the following line in your site.ini.append.php file:

[DebugSettings]
DebugOutput=enabled

Debug output main area (1)

This section displays errors, warnings, notices and other important information from the eZ Publish kernel, modules, extensions and so on. This section also displays SQL queries when SQLOutput is enabled. Debug settings such as SQLOutput are described later in this article.

Debug output timing points (2)

This section displays timings and the amount of memory spent on processing modules or template blocks. PHP must be compiled with the --enable-memory-limit option in order to be able to show the amount of used memory. This section also displays timing points and accumulated time in your templates. These functions are described below, and are used to test the performance of your template code.

Adding timing points in the templates

You can manually add timing points to eZ Publish templates. This is useful to see how much time specific parts of complex templates take to process.

The example below demonstrates how the debug-timing-point mechanism can be used to measure the time it takes to fetch and print the names of all nodes that are below node number 2.

{debug-timing-point id='test'}

{def $nodes=fetch( 'content', 'tree', hash( 'parent_node_id', 2 ) )}

{foreach( $nodes as $node )}
{$node.name|wash()}
{/foreach}

{/debug-timing-point}

Here is the sample debug ouput for the timing points:

The timing points section of debug output

One thing to note here is that the last and second-to-last times in the timing points are usually different. The second-to-last point, labelled "End", shows the total processing time. The "Total runtime" also includes the flushing of the output buffer, which means that the content has been sent to the browser. If you have a slow connection, there will be a larger difference between these numbers.

Timing points in PHP

When you are developing eZ Publish extensions in PHP, you often need to find how much time the different parts of your code take to process. Timing points can be added with the method addTimingPoint in the eZDebug class. This enables you to track different parts in the code and display the time spent between the different points in the debug output.

PHP code example:

eZDebug::addTimingPoint( "My module start processing" );
...
...
eZDebug::addTimingPoint( "My module end processing" );

Debug output time accumulators (3)

This section of the debug output displays timing information about various parts of the system, such as template processing, character set conversions, XML processing and information about SQL queries. This section also displays the results from the debug-accumulator template function.

Accumulated time with debug-accumulator

If you have groups of tasks that span several templates and you want to measure the total time spent on the tasks, you can use the time accumulator functions. All time accumulated with the same ID is shown in the same summary in the debug output.

This example demonstrates how the debug-accumulator mechanism can be used to generate debug statistics based on the encapsulated template code.

{debug-accumulator id='test'}
{def $nodes=fetch( 'content', 'tree', hash( 'parent_node_id', 2 ) )}

{foreach( $nodes as $node )}
   {$node.name|wash()}

{/foreach}
{/debug-accumulator}

The time accumulators section of debug output

Accumulators in PHP

When you have repeating code in your extensions, you can add an accumulator to summarize the time spent on the specific code. The example below shows how you can add an accumulator around a MySQL string conversion. This will be summarized in the group mysql_total in the debug output with the label "String conversion in MySQL".

PHP code example:

eZDebug::accumulatorStart('mysql_conversion', 'mysql_total', 'String conversion in MySQL'); 
... 
... 
eZDebug::accumulatorStop('mysql_conversion');