Web Mozarts

Hi! A warm welcome to Web Mozarts also from my side. It took some time to write my first post, but here it is!

Your app is slow? If the symfony web debug toolbar doesn’t give you the details you want, you can take a real deep look into your application using the profiling options of Xdebug.

In this tutorial we will set up Xdebug to profile your application and then we’ll analyse the output with KCachegrind.

By the way: Xdebug has a lot of other useful features. One that comes automatically is the nicely formated php debugging output in case of errors including the full call stack. KCachegrind on the other hand has very interesting graphical output features like the call graph. In the case of symfony the call graph can be like an interesting expedition into the functionality of the framework.

Installation

We’ll do the installation using Ubuntu Linux, but it works similar for other unixes or even Windows with a WAMP stack. Ah yes – we assume you have the correct environment for symfony installed (Apache, PHP5, …).

KCachegrind is not available for Windows. You can use WinCacheGrind instead although it doesn’t provide the graphical goodies.

Download and install:

sudo aptitude install php5-xdebug kcachegrind

Ubuntu automatically inserts the Xdebug module in the php ini files:

# /etc/php5/conf.d/xdebug.ini
zend_extension=/usr/lib/php5/20060613+lfs/xdebug.so

Now let’s restart apache to load the new configuration:

sudo apache2ctl restart

Let’s provoke an error and let us see if Xdebug works. I put an invalid function call into a php script:

// apps/frontend/modules/myModule/actions.class.php
class myModuleActions extends sfActions
{
  public function executeIndex()
  {
    invalid_function();
  }
}

Now we get the typical Xdebug output including the call stack in the browser, so we know it works:

Enable profiling

The profiling capability of Xdebug has to be explictly enabled because it produces A LOT of output and slows down the application serverely.

If you use .htaccess for your symfony project this is the easiest way to enable the profiling:

# web/.htaccess

# append at the end of the file:
php_value xdebug.profiler_enable 1
php_value xdebug.profiler_output_dir /tmp

If you don’t use .htaccess, or if you want to profile a cli php script, you have to enable the profiling in your php.ini (cli stands for command line interface). Example for the cli:

# /etc/php5/cli/conf.d/xdebug.ini

# append at the end of the file:
xdebug.profiler_output_dir = "/tmp"
xdebug.profiler_enable = 1

Don’t forget to restart apache if you changed the php.ini config!

Data galore…

Ok, let’s profile something! Just fire up your webbrowser and load any page of your local symfony project.
Xdebug now creates a “cachegrind” file like “cachegrind.out.22076 in your /tmp/ directory.

Here’s how a cachgrind file looks like:

version: 0.9.6
cmd: /var/www/ullright/web/index.php
part: 1
 
events: Time
 
fl=php:internal
fn=php::realpath
38 98
 
fl=/var/www/ullright/plugins/ullCorePlugin/lib/vendor/symfony/lib/autoload/sfCoreAutoload.class.php
fn=sfCoreAutoload->__construct
50 93
cfn=php::dirname
calls=1 0 0
38 2
cfn=php::realpath
calls=1 0 0
38 98

It basically records which function was called from which script file, how many times it was called and how long the execution took.

Now that isn’t really human readable, is it?

So let’s open the cachegrind file with KCachegrind. It looks something like this:

So what have we got here? On the left side you see the “Flat Profile”. A list of all function and method calls. From left to right:

• Incl. – The cost of the function including all child functions
• Self – The cost of the function itself
• Called – How many times a function was called
• Function – Which function
• Location – Script file

A good starting point is to click on “Called” to see which functions are called the most often. It’s also interesting to order by “Self” to see which method itself took the most time.

On the right side I selected the tab “Call Graph” which shows the sequence of the function calls starting with “{main}”. For symfony it’s usually “web/index.php”.

The number of nodes in the call graph is limited by the relative percentage of the execution time. Per default only functions that take more than 5% of the execution time are displayed. Get a more detailed graph by right clicking into the call graph and selecting “Graph -> Min. node cost -> 1%”. You can also doube click on any node to see a more detailed child-graph.

Here is a nice detailed graph showing the internals of a doctrine query.  I’d like to invite you to explore your symfony app using the call graph – it surely is an interesting journey and you can learn a lot about the architecture of symfony.

Coming to an end I’d like to hear about your experiences and findings about performance profiling:

• What tools do you use?
• What are your best practices?

Looking forward to interesting discussions – have a nice day!

No related posts.