How to enable Magento Profiler

Magento comes with a very useful tool called the Profiler. If you’ve ever wanted to know how long a piece of code takes to run, or which parts of your website are running slow, then the profiler is possibly the best tool for the job.

Firstly, you have to turn it on.

In your admin area, go to System > Configuration > Advanced > Developer > Debug, and switch Profiler to Yes for the appropriate store view:

profiler

Then load any page on your front end, and scroll to the bottom.
You’ll see a link to [profiler]. Click it and you’ll see this:

profiler

Not particularly useful in it’s current format. That’s because the Profiler is switched off by default.
To enable it, open index.php file located at the <MAGENTO_ROOT> folder. Find the line with #Varien_Profiler::enable(); and un-comment it (remove the hash sign #):

Varien_Profiler::enable();

Reload your front end page and the profiler will be spitting out all sorts of information.
The information is hierarchical, but it isn’t displayed as such so it can be difficult to understand:

profiler

How to enable SQL Profiling

To display in the Profiler information about SQL queries, such as Number of queries executed and the time taken for it, Average query length, Queries per second, Longest query length, and Longest query you need to enable SQL Profiling.

1) To enable SQL Profiling, you need to enable Profiler from admin as described above.

2) Open the local.xml config file located in <magento_root>/app/etc/ folder and add the node <profiler>true</profiler> into the global/resources/default_setup/connection/:

<default_setup>
            <connection>
                <host>localhost</host>
                <username>root</username>
                <password>astral</password>
                <dbname>feedexport1810</dbname>
                <initStatements><![CDATA[SET NAMES utf8]]></initStatements>
                <model>mysql4</model>
                <type>pdo_mysql</type>
                <pdoType></pdoType>
                <active>1</active>
                <profiler>true</profiler>
            </connection>

3) Save the file and clear the cache.
Now if you refresh the page, you will see the SQL Profiling output below the code profiling results:

profiler

The first thing to note is the memory usage at the top. The numbers are in bytes, so divide the number by 1048576 to get the number of megabytes of RAM used to load the page. High memory usage can affect loading speeds, especially when lots of users are loading lots of different pages.
In the table the following headers Code Profiler, Cnt, Emalloc, RealMem show every step the system takes in the loading of a page, where:

  • Code Profiler - the name of the block of code being executed
  • Time - The time it took to complete in seconds
  • Cnt - Short for Count, represents the number of times this individual block ran to generate the output
  • Emalloc - The amount of memory PHP assigned to this single operation, Its a mix of core PHP memory_get_usage() function without true parameter passed to it, minus timer values
  • RealMem - The actual amount of memory used to perform the operation. It is final value is also obtained trough memory_get_usage(true) function minus timer values but this time with true parameter passed in.

How to use information from Profiler

Let us bring some light on all this information. The execution time param is the most interesting for us. However, it’s a bit tricky. If you try to make the sum of all values of the column, you won’t get the actual execution time. Very often the profiler’s method calls are placed one inside the other. On the screenshot above you can see that mage::dispatch::routers_match has the biggest execution time (2.6948 seconds). However, it does not mean that there’s something wrong with the routers match operation in Magento. In that case, other profilers records are placed ‘inside’ the routers match record. That should be kept in mind. If you go down on the list you will find the most nested process. Let’s check the real example.

Look at the following image:

profiler

Note that frontend/base/default/template/page/html/header.phtml execution time is quite long – 1.8251 seconds. We can see the set of header’s child templates in the profiler’s list at the bottom of frontend/base/default/template/page/html/header.phtml. The slowest child is frontend/base/default/template/custom_extension/cart.phtml. Ok then, it’s a custom extension in our store which displays the shopping cart contents as a pull down menu in the header. If we disable this extension we will get the page load performance increased by more than one second.
There are two major reasons of the bottlenecks like this one:
1) The first one – it’s a bad code. An extension might have a big number of unnecessary database queries or the logic is simply bad organised and, as a result, resource consuming. In that case, you can ask your developer to check the extension or try to fix it yourself.
2) The second reason is the need to get some additional information from the database or make some additional operations to have the necessary information. That is exactly what happened in our case: the header’s shopping cart pull down menu extension makes the additional database requests to get the shopping cart items information. By default (when there’s no additional shopping cart information on each page), Magento does not fetch this information. So, in cases like this one you should think twice: worth the header’s shopping cart one second of the page loading time or not.

Not always .phtml templates execution time reflects the bottlenecks. It’s useful to pay attention to OBSERVER records in the profiler’s report. Some extensions might execute an additional logic on the different system events. Just check what observer is the slowest and make sure that it’s not Magento core observer. Usually, the developers give names to their observers by adding a vendor name, something like this: developer_extmenu_add_topmenu_items. So, if some custom observer slows down your system you should either disable the extension or investigate it for a reason of the bottleneck.

profiler

How to add Profiling to custom module code

To add profiling to custom module code add next lines:

Varien_Profiler::start('LabelForCodeFragmentToProfile');

///... here some code we like to get statistics for

Varien_Profiler::stop('LabelForCodeFragmentToProfile');

If cumulative time of execution for this code is more than .0001 second it will be shown in profiler table with cumulative time, number of executions and cumulative memory consumption.

General Manuals