Meta Matters

Comments and discussion of (mostly) Joomla-related topics by the author of MetaMod and Chameleon.

Nov 15
2010

PHP “Profiling” as a debugging tool for Joomla!

Posted by: metamodguy

Tagged in: PHPdevelopment

PHP logoOver the last couple of days I have been doing final testing on an update to MetaMod Pro, introducing compatibility with JoomlArt’s wonderful T3v2 template framework. Something I noticed was that pages were taking 5-10 seconds longer to load in the T3v2 template than they were with any of the other templates I have installed.

If this was Java I’d be reaching for the Java profiler in NetBeans. But Joomla is in PHP... I’d never come across that kind of profiler for PHP before...

This is how I tackled the problem and found a great new tool for site diagnostics in Joomla.


A “profiler” in this case is a piece of software which monitors PHP, tracks all the PHP functions and methods that get called, then records how long is spent in each one. All this information gets saved into a data file, which is typically analysed by a separate application.

The data and visualisations you get out of the profiling system are invaluable for finding out what’s actually taking all the time in an application. You get to see a tree of all the functions/methods that have been used, and the amount of time that each function/method and branch of the tree has taken.

Anyway, I found what I was looking for: Xdebug. In the end it was quite easy to set up, so I wanted to share how I did it. This is very worthwhile for any Joomla component developer, or even technically-minded site admin to find out exactly why a site is running slowly, and what can be done to speed it up.

[Xdebug can also be used for single-stepping through PHP code and I use it regularly via NetBeans for examining Joomla. That’s a topic for a future post.]

Prerequisites for PHP Profiling

  • XAMPP (which I was using anyway) as the local web server. I use this on OSX instead of the built-in web server (“Web Sharing”) since it’s easier to mess with configure.
  • The Komodo pre-compiled Xdebug libraries for Xdebug
  • Webgrind, an easy-to-install PHP application for analysing the profiler data files
  • Optionally, kcachegrind, a desktop app providing superior analysis. I used the Mac Ports system to compile this on OSX, but I believe it’s easier to install on Windows or Linux.

Steps

I set this up on MacOSX, but the steps are going to be very similar on Windows too.

  1. Install XAMPP. I assume you know how to set this up...
  2. Install Joomla in XAMPP and ensure it’s running properly.
  3. Download the Komodo XDebug libraries appropriate to your server (Mac/Windows/Linux). Find them here under “Komodo IDE Client 6 => PHP Remote Debugging Client”
  4. Unzip the zip file. Inside you’ll find several folders named 5.0, 5.1, 5.2, 5.3 etc. corresponding to different versions of PHP. The current version of XAMPP is running PHP v5.2, so copy the file 5.2/xdebug.so and put it directly into your root XAMPP folder (final path on my machine: /Applications/XAMPP/xdebug.so).
  5. Edit the file XAMPP/etc/php.ini, and add the following lines to the very end of the file:
    [xdebug]
    ; customise path on next line depending on location of your XAMPP folder
    zend_extension=/Applications/XAMPP/xdebug.so
    xdebug.remote_enable=on
    xdebug.remote_handler=dbgp
    xdebug.remote_host=localhost
    xdebug_remote_port=9000
    ; xdebug.profiler_enable=1
    xdebug.profiler_enable_trigger=1
    xdebug.profiler_output_name=cachegrind.out.%t-%s
    ; Customise next line depending on where you are storing
    ; your output files. This folder has to exist and be writable by
    ; the web server.
    xdebug.profiler_output_dir=/Library/Webserver/Documents/grind-out
  6. Create the folder that you stated in the last line. This must be writable by the web server. On OSX I selected the folder, did a “Get Info” and assigned read-write access to “everyone”.
  7. Restart the web server using the XAMPP Control application.
  8. Fire up a web browser and go to http://localhost/joomla/whatever to make sure it’s still running.
  9. To confirm that it has been installed correctly, go to the administrator section of Joomla and go to the menu Help => System Info => PHP Information. Search on the page for “xdebug” and you should see a bunch of parameters the same as what you added to the php.ini config file in step 5.
  10. Download Webgrind, unpack it and move it into your web root folder, so you can access it at http://localhost/webgrind
  11. Edit the file webgrind/config.php if you want to, but it’s probably going to work right out of the box.

Start your engines

We’re now ready to start profiling for the first time. When we start profiling, the pages are going to load a little slower, and the data files can be up to a couple of hundred MB each, so be sure you have enough disk space!

To start the profiler, we add the URL parameter “XDEBUG_PROFILE=1” to any page URL. It creates one big file for each time we do it.

e.g. I call up this page:

http://localhost/j157/index.php?option=com_contact&view=contact&id=2&Itemid=61&XDEBUG_PROFILE=1

...and this generates a data file here:

local:~ user$ ls -l /Library/WebServer/Documents/grind-out/
total 684128
-rw-r--r--  1 nobody  admin  108507821 16 Nov 12:56 cachegrind.out.1289865372-_Library_WebServer_Documents_j157_index_php

Nearly there! Now we just want to analyse the file in WebGrind.

Call up http://localhost/webgrind and click on the Update button:

top of WebGrind main window

Since WebGrind is running under PHP, it automatically picks up the data directory from the PHP configuration, and by default uses the most current profile data file.

After a couple of minutes we get the first display:

Webgrind main window

This is sorted by “Total Self Cost” which is the percentage of time PHP spends directly inside in each function/method. The column to the right shows the total inclusive cost - i.e. the percentage of time spent in each function/method including inside any functions/methods called by that function/method in turn.

“Invocation Count” is the number of times that the method was called.

It’s now easy to see what’s going on. There’s a Javascript minifier (JSMin) at work. It looks like it’s being called at JSMin::minify, and from that point on it’s taking 81.32% of the CPU/time.

We can find out some more about it, including examining the sources, by clicking on various parts of the interface:

Webgrind window, showing additional info and source code

Conclusion

In this case, the behaviour was not strictly a bug – when you have “Development Mode” set in a JoomlArt T3v2 template, the JS compressor is set to work on every page load and doesn’t cache the output. Perhaps I just have a lot of JS on my test site... but now I know exactly why this is occurring, and could tweak it if necessary.

And I have a great new diagnostic tool.

Joomla component developers: you need to become familiar with this tool!

Postscript

kcachegrind is supposed to be even better at analysing the output, so I had a bash at installing it. After a bit of trial and error I got it running with Mac Ports (sudo port install kcachegrind).

OMGoodness this is impressive, and much faster than Webgrind. I love being able to compare the amount of CPU used for different plugins, and spot the bottlenecks. There’s more info here than I’ll ever need.

I think I’m in debug heaven.

//end.


blog comments powered by Disqus