How to pinpoint Joomla performance issues

There are many many articles and blog posts about Joomla Performance and guess what, here is one more.
However this one is definitely targeted to Joomla and php experts as it focuses on the page generation time. I'll post another article soon about the page rendering time.
Please note the subject of this article is to pinpoint a loading time issue. Not to solve it.

So how do Joomla! generates a page?

First of all, everything starts with one single file : index.php. This one will then load the appropriate component, trigger plugins and finally render a page with modules. That means a lot of php files that will be loaded, parsed, executed. Not to mention the database queries.

First of all, let's activate the debug system plugin and activate debug in Joomla configuration. If you are familiar with Joomla! you know already about the debug plugin that will append debug information and traces to the page.

joomla-debug-console

 

It comes with 4 sections:

  • Session shows the variables stored in session
  • Profile information shows some execution time and memory usage and this is the one I will focus on.
  • Memory usage shows the total memory used to generate the page
  • Database queries being executed and how many time a similar query was executed

Additionally, you can see the language files that are loaded if you enable language debugging in Joomla! configuration.

debug-modules

 

You can see here a list of modules that are parsed and you can clearly see that the mo_vm_simple_product_slideshow is taking 0.572 seconds to load and 4.729 Mb. (always compare the beforeRenderModule to the afterRenderModule of the same module)
That's 35% of the generating time !!!

Looks like we found the culprit but... maybe not.
It happens that the current page is the home page (com_content) and the module needs to load some Virtuemart classes and product informations.
Blaming it solely on the module would be too much of a shortcut and will see later that Virtuemart might not be either.

This debug plugin is kinda great but we miss some information in my opinion.
Let's start by adding the component loading time to the trace:

debug-component

 

Now we can see that the main component loaded (com_content) took .03 seconds to execute. That's 17.5% of the total page generating.
To add this logging information, you need to implement a hack in Joomla! core library files. To do so, open the file

libraries/joomla/application/component/helper.php

and search for the code 

// Execute the component.
$contents = self::executeComponent($path);

Replace with 

// Execute the component.
if (constant('JDEBUG')) {
JProfiler::getInstance('Application')->mark('beforeExecuteComponent ' . $option.' ('.$task.')');
}
$contents = self::executeComponent($path);
if (constant('JDEBUG')) {
JProfiler::getInstance('Application')->mark('afterExecuteComponent ' . $option.' ('.$task.')');
}

This will add markers right before and after the component is executed.

Let's go even further.

Joomla is mainly composed of components, modules and plugins. These last one do not appear here so we will add some profile information for those too.

Joomla plugins are loaded by folder and then triggered by events. This is very usefull to extend core functionalities but if too many of them are loaded and not properly coded, many pieces of code will be executed even if not necessary.

To add plugin profiling, open the file

libraries/joomla/event/dispacher.php

locate function trigger and the code 

// Fire the event for an object based observer.
if (is_object($this->_observers[$key]))
{
$args['event'] = $event;
$value = $this->_observers[$key]->update($args);
}
// Fire the event for a function based observer.
elseif (is_array($this->_observers[$key]))
{
$value = call_user_func_array($this->_observers[$key]['handler'], $args);
}

suround it with profiling marking:

if (constant('JDEBUG'))
{
$pluginName = '';
if (is_object($this->_observers[$key])) {
$pluginName = get_class($this->_observers[$key]);
}
JProfiler::getInstance('Application')->mark('Execute Plugin ' . $pluginName.'::'.$event.' - START');
}
// Fire the event for an object based observer.
if (is_object($this->_observers[$key]))
{
$args['event'] = $event;
$value = $this->_observers[$key]->update($args);
}
// Fire the event for a function based observer.
elseif (is_array($this->_observers[$key]))
{
$value = call_user_func_array($this->_observers[$key]['handler'], $args);
}
if (constant('JDEBUG'))
{
JProfiler::getInstance('Application')->mark('Execute Plugin ' . $pluginName.'::'.$event.' - END');
}

And voilà! Plugins execution time are added to the debug console.

debug-plugins

 

You can now see all the plugins that are loaded, at what step (before executing the component, in the component itself, after..) and you will immediately notice that some plugins are executed many times.

If one of them is not optimized, and over the top is executed several times.. well you pinpointed something for sure.

As I mentioned earlier, This is more a hint on how to pinpoint a generating time issue, not how to fix it. This really depends on the components you use and or develop.

A few tricks though:

  • Uninstall or unpublish plugins you don't use
  • Plugins that are meant for admin purpose only should be set the access 'special' so they are not even executed for public but will continue working on the backend
  • Unpublish modules that are not used even if they are not displayed (page none or position none)
Top