Why use Magento’s Varien profiler?
We all know that Magento is a powerful tool for online sales. It’s well supported, has a vast array of features and has a wealth of extensions to enhance performance and provide additional functionality. However, one of the downsides to the Magento platform is performance drop-off with the age of the installation. All systems gradually decrease in performance, due to additional extensions and content being added, reports saved and logs generated. Magento is not alone with these issues; however having such a rich feature set and resulting intricate code base, can lead to some bloatedness of older systems. To help combat this we can use one of Magento’s most powerful developer features: the profiler.
About the Profiler
The Varien profiler can tell you in intricate detail which blocks of code are used in the loading of a slow page, and how long it takes each block to complete its task. In this article I will be going over the bare bones of how to use the Varien profiler. This information is aimed at experienced Magento developers, and as such, we hold zero responsibility for breaking your website, or causing service degradation as a result of using the profiler. If you don’t know PHP or the intricacies of Magento’s core, look away now.
There are some downsides to using the profiler. Firstly, it should never be run on live sites, as it exposes exactly how a page loads, and this can provide intimate details of how your system is configured; information that would be highly valuable to anyone trying to compromise your store. As such, it should only be run in a development environment. Secondly, there will be additional overhead when running the system with the profiler switched on, as it will be logging the execution of commands during loads.
That being said, it is an invaluable tool in finding the points in your system configuration where slow down is occurring the most.
How to enable the Profiler
To enable the bare bones of the profiler, log into your Magento back end, Go to the System dropdown, and then go into Configuration. Next, go to Developer in the Advanced section of the right hand menu. Switch to whichever website / store you want to run the profiler on, and in the Debug dropdown, set Profiler to Yes. Finally click Save Config in the top right.
At this point the profiler is switched on, but we need to tell the profiler what to profile. The default catch-all solution is to go into the index.php file in the root install. Find the line with #Varien_Profiler::enable(); and un-comment it ( remove the hash sign).
Now if we go to any of the front facing pages, including the home page, at the bottom will be the profiler output.
What the results mean
To the untrained eye, this will look like a bunch of random words and numbers, but enlightenment can be found in this madness. 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. In our example we used 41.75mb of RAM to load the page, which isn’t that bad. High memory usage can affect loading speeds, especially when lots of users are loading lots of different pages. Next is the table. This outlines every step the system takes in the loading of a page. The columns are as follows:
- Code Profiler: This gives the name of the block of code being executed
- Time: The time it took to complete in seconds
- Cnt: Short for Count. This represents the number of times this individual block ran to generate the output required
- Emalloc: The amount of memory PHP ( the programming language on which Magento runs) assigned to this single operation. This is again represented in bytes.
- RealMem: The actual amount of memory used to perform the operation.
Now we know what the headings are, we can start to look at the table. The list is sorted in order of execution. The top one will always be Mage, as this is the Magento root system. This, in turn, will load the Magento configuration (the next line). This then triggers the loading of system models, which leads to loading of the appropriate designs based on the link you entered, which in turn may load more data, and so on. In essence, think of the table as a tree, with Mage as the trunk, and all the little sub-processes coming together and filtering upwards; combining into one entity, this being the requested page.
If we look at our table, we can see that nothing took over a second, and nothing was called any more than a couple of hundred times. So let’s look at some of the worst offenders.
Interpreting the Results
Mage_Eav_Model_Config::get EntityType was called 152 times. This isn’t that surprising as we are loading a product so this is being called each time we want to know an attribute about the product. The page has its price, name description and other data, and that’s just data used on the front end. Thus, we can expect a fairly high number of calls to this, especially if we are using custom product attributes.
Similarly, if we look at mage::dispatch:controller:action:catalog_product_view, it’s taking 0.5640 seconds to run. Again, whilst being higher than the majority of items in the list, it is to be expected, as this is the action that pieces together all the bits of product information into one block of data to be displayed on the page. As you can probably tell, identifying what the actions do from the name takes a real understanding of how Magento works, so it pays to employ someone who knows Magento well, and ideally a certified developer, to do this investigative work. As this is a fresh install, there are no processes that take an extraneous amount of time, iterations or memory.
Locating the problems
But let’s say there is something in the list that does catch our eye. Let’s say Mage_Core_Model_Design_Package::getFilename has really high memory / time usage.
If we are about to start our investigative work, we need to first log into our hosting panel, and create a backup in case something goes awry. The next task is to try and identify where the code resides. In this case it’s easy: in the /app/code/core/Mage/Core/Model/Design folder, in the file named Package.php, and the function in this file is getFilename. The first thing to note is to NEVER edit files inside of app/code/Core. If you break this rule, you are almost guaranteed to break your system when you do a Magento upgrade, and you run a very high risk of breaking Magento extensions also. app/code/Core is the beating heart of Magento, so it should never ever be altered.
If, however, we are in a situation where the core files are causing issues, first look at the way the store is set up; if you are having performance issues in the core, it’s probably a bad configuration. Do some research with your favourite search engine to see if there are known problems here, if anyone else is having the same issues, and if there are solutions that don’t involve editing the core. If this fails to yield any results, you can override the core code in app/code/local. This local code pool allows you to safely override the core, without putting future updates in peril, but this may still cause issues with extensions. To do this, you create a copy of the file in the local folder with the same directory structure, in our case, /app/code/local/Mage/Core/Model/Design/Package.php. So we have our file, which is safely overridden, and we know the function. The next point is to add some profiling fragments around the blocks of code you suspect of being at fault. Add:
Varien_Profiler::start('PackagePHPFragmentNameHere');above and
Varien_Profiler::stop('PackagePHPFragmentNameHere');below the suspect blocks. This will add extra data to the profiler output, telling you exactly what occurred between the two lines. At this point, you are going to have to rely on your developer skills, as there are an infinite number of methods to examine your code further, but that will have to wait for another blog article.
Finding problems with extensions
We’ve talked about problems in the core, but more often than not, it will be your extensions that will be causing your slowdown. Extensions provide additional functionality, which requires extra work on behalf of the server and thus time and memory.
Let’s say in our profiler that OBSERVER: thisextension_core_block_abstract_to_html_after is standing out. First thing is to search for this line online to try and determine which extension it resides within. If you do manage to find the extension, then go into your Magento Connect extension manager (System->Magento Connect->Magento Connect Manager) and log in with your standard Magento credentials. Click Check for Upgrades, and see if the troublesome extension has an update available. If not, then you can either contact the extension developer, or employ the profiler fragments, as spoken about above, to try and narrow down the cause. Again, at this point, it will be down to you to try and debug the code, line by line, to try and find the culprit.
That's It
Finally, there are the last few lines under the table. These tell you about the database queries that were executed in the request. If the hunt for problems in the core has not returned any useful results, check these blocks for long running queries, to help locate the problem.
Once you have all the profiler outputs you require, turn off the profiler in the back end and in index.php.
This article scrapes the tip of the iceberg on what the profiler can accomplish, but we hope it has given you the confidence to give it a try, and see which extensions or core routines are slowing your Magento system down.