ModGrind – Magento Performance Profiling

Posted on

ModGrind is a tool that we’ve developed internally at iWeb for profiling Magento sites. We use it to diagnose speed problems on sites and to test our assumptions about where time is being spent.

It’s a wrapper around two other tools (one of which was also written at iWeb) – Xdebug and parse-cg.py.

Xdebug is a PHP Zend extension; it has several functions the most important of which is that it’s capable of profiling PHP applications and creating profile files in the same format at callgrind uses.

While this isn’t a an official standard of any kind, its use is so common that various tools have sprung up which can read this format of file. One that iWeb use heavily is QCachegrind (a version of KCachegrind which doesn’t require the KDE libraries).

QCachegrind is written using the Qt framework so it’s portable between Linux and Mac OS X (and potentially, Windows). Most of us develop on Macs, either directly or using Vagrant virtual machines running Linux, so this is really convenient, but there are times when loading up a large profiling run and picking through it is too time consuming and you want to get a general idea of the location of a performance bottleneck.

It’s also cumbersome to use QCachegrind when testing a site which has already gone live or for which the staging environment has special features (like access to a customer’s warehouse database) – you need to copy the cachegrind.out files down to your workstation.

Typically these files grow in line with any performance problem meaning that the worse the performance issue, the harder it is to debug.

Enter ModGrind.

ModGrind will run a single PHP request under the Xdebug environment. Once that’s completed, it locates the correct cache file and passes it to parse-cg.py. parse-cg.py will then parse through the file and look for how much CPU time was spent in each modman module.

Because of iWeb’s heavy use of modman to structure our projects, it becomes really easy to see where your CPU time is being spent. Here’s the output from one of our sites:

73532 mana-seo-layered-navigation-plus
112402 mageworx-seo-suite-ultimate-3-7-7
421812 iweb-wordpress
1141177 Cm_Cache_Backend_File

 

This is actually quite a well behaved site- it’s live and we’ve profiled it heavily to deal with large amounts of traffic.

One of the first lessons in using ModGrind (or using QCachegrind) is that all of these figures are essentially relative – you can use it to show that a large percentage of time is being spent in one plugin or module, but comparing the absolute numbers between two different sites (or even two different types of page on the same site) isn’t useful.

Infact, the great thing here is how much time is being spent in Colin Mollenhour’s Cm_Cache_Backend_File module – this is a very efficient Magento caching module (see this cache benchmark script if you want to test for yourself) and if it’s being used heavily that suggests that much of the page is able to be served from Magento’s own cache, and not regenerated each and every time.

Of the remaining modules, our own WordPress integration module consumes most of the time (which seems reasonable, as the page that we’re profiling is actually a news page) – and a background amount of CPU is being spent on the Mageworx SEO Suite and Mana SEO Layered Navigation Plus plugins.

These are two third-party plugins that this site relies heavily on, and they aren’t taking a significant amount of CPU time, so if we felt the need to profile this page further, we would focus on the WordPress module.

Now that we’ve shown a healthy ‘after’ case, lets examine a site with speed issues. Several modules have been installed and one (or more of them) is contributing to a considerable slow down.

$ ab -c 1 -n 10 http://dev.test.iweb/ | grep 'mean,'
Time per request: 78.111 [ms] (mean, across all concurrent requests)
# Before installing plugins

 

$ ab -c 1 -n 10 http://dev.test.iweb/ | grep 'mean,'
Time per request: 1061.131 [ms] (mean, across all concurrent requests)
# After installing plugins

 

Wow, that’s a big difference! One option available to any developer is to disable the modules one by one in Magento’s admin and retest each time to locate which is causing the slow down.

Proper testing hygiene suggests that you clear the caches each time, and run the tests several times, to avoid any ‘warming up’ costs. Of course, you should also do all of this on a machine which is not being used for other tasks.

Needless to say, arbitrarily turning off modules, clearing caches and benchmarking on a live server are not very practical – they will have an impact on production and they are time consuming jobs.

ModGrind can quickly show us the most CPU-hungry modules.

$ modgrind dev.test.iweb /
21464 quick-shopping
21704 iweb-footer-links
39299 iweb-wordpress
41122 iweb-data-import
55575 addthis-sharing-tool
68250 iweb-seo-redirect
120620 Cm_Cache_Backend_Redis
288328 ebizmarts-sagepaysuite
514471 one-step-checkout
653230 iweb-banners
655110 oak-criteo-onetag
842988 fast-asynchronous-re-indexing
874065 aw-countdown
1025896 pronav-3_5
1528591 fooman-speedster-advanced
5366754 ontap-merchandiser
13312307 iweb-homepage-tabs
20877195 iweb-default
23811206 mana-seo-layered-navigation-plus
27675369 oak-furniture-superstore-skin
78600152 adjustware_deliverydate

 

Once they’re identified they will need to be profiled in depth, or disabled and the impact measured, but now we’ve whittled the probable plugin list down to just three entries, more than cutting the work required in half.

How does it work?

Here’s the BASH script:

[pyg language=bash]#!/bin/bash
HTTP_HOST=”$1″ REQUEST_URI=”$2″ php -d xdebug.profiler_enable=1 index.php >/dev/null
LATEST=$(ls -t /tmp | grep cache | head -1)
python /usr/local/bin/parse-cg.py /tmp/$LATEST[/pyg]

It sets the HTTP_HOST and REQUEST_URI headers – without these the router in Magento won’t know how to direct your request, and it will try and serve a redirect to a URL it *does* know how to handle.

We enable the PHP profiler on the command line. The alternative is to enable it in the PHP configuration, which causes crons to run slower; sometimes much, much slower.

It takes the latest file with ‘cache’ in the name and passes it into parse-cg.py.

The cache grind files contain data like this:

[pyg]fl=/home/testweb1/public_html/.modman/iweb-wordpress/app/code/local/Iweb/Wordpress/Controller/Router.php
fn=Iweb_Wordpress_Controller_Router->initControllerRouters
1338 41
cfn=Varien_Event_Observer->getEvent
calls=1 0 0
6 45
cfn=php::Varien_Event->getFront
calls=1 0 0
6 117
cfn=Mage_Core_Controller_Varien_Front->addRouter
calls=1 0 0
7 20[/pyg]

This is documented on the valgrind website, but the gist of it is that lines starting with ‘fl=’ list the filename that a given record relates to, and the first line after that with no prefix contains the source position and inclusive cost of the call.

These two can be matched by these regular expressions. We’ll also set up a simple state machine to denote whether we are inside a profile record or not.

[pyg language=python]states = (‘DEFAULT’, ‘HAVE_FILE’)
fl = re.compile(‘^fl=(.*)’)
num = re.compile(‘^d+ (d+)’)
state = 0
current_file = ”
inclusive = True[/pyg]

We’ll match a line starting with ‘fl=’ and check that its in a modman folder. If it’s not, we’re likely just profiling core Magento, and other tools exist to do that job.

[pyg language=python]f = file(sys.argv[1], ‘r’)
d = dict()
for line in f.xreadlines():
line = line.strip()
if fl.search(line):
x = fl.search(line)
if not ‘modman’ in x.groups(1)[0]:
continue
current_file = x.groups(1)[0]
current_file = re.sub(‘.*modman/’, ”, current_file)
current_file = current_file.split(‘/’)[0]
state = 1
continue[/pyg]

If it is, we switch into the second state and we note what file the fl= line referred to, and we move on to the next line.

Next time around, if we don’t match an ‘fl=’ line, we will check if the line contains the two numbers that we’re looking for. If it does, we add the second number to the total for this file. (We don’t care about the first number)

[pyg language=python]if state == 1:
if num.search(line):
x = num.search(line)
i = d.get(current_file, 0) + int(x.groups(1)[0])
d[current_file] = i
if not inclusive:
state = 0[/pyg]

[ Steely-eyed readers may have noticed that there’s an ‘inclusive’ flag for parse-cg.py – this counts all of the methods in Magento core that each module calls. If profiling the actual code of the module doesn’t give satisfactory results then turning this on can highlight modules that use slow parts of Magento, or simply make lots of calls to core ]

Finally, once there is no more data to read, we exit the loop, sort the results to be in order of CPU time used and print them out.

[pyg language=python]x = [(v, k) for k, v in d.items()]
x.sort()
for v, k in x:
 print v, k[/pyg]

Want to discuss a project?

Talk to our Magento experts on 01785 279920

Request a callback