Jan 30 2009

How to profile your PHP scripts with Xdebug

Performance is a big issue on the web, if you pages take too long to load then people will go elsewhere. Sometimes your problems can be solved with cache control on your server, but still some cases require optimisation of your code. For this task, you should be using a technique known as ‘profiling’ – essentially a debug log of what your script or program did during execution, which functions were called and how long it took. It gives you a great glimpse into what it is that is taking too long to execute which means you have something concrete to look at when you need to optimise your system.

Fortunately, PHP has a couple of debug tools available. Today I will be looking at Xdebug, and in particular its profiling functionality. Grab Xdebug and enter these lines into your PHP.INI file:

zend_extension_ts="c:/path_to_xdebug/php_xdebug-2.0.4-5.2.8.dll"

; General debug settings
xdebug.remote_enable=1

; These are the profiler settings
xdebug.profiler_enable=1
xdebug.profiler_enable_trigger=1
xdebug.profiler_output_dir="c:/xdebug_profile_logs/"
xdebug.profiler_output_name="cachegrind.out.%t"

Be sure to make ‘zend_extension_ts’ point to the correct location for the downloaded Xdebug library and ‘xdebug.profiler_output_dir’ point to where you want the profile logs to be saved. Restart your web server and it should be good to go. You can run a phpinfo() script to check that Xdebug is loaded, it should be listed as a module if it is.

The next step is to run your script that you want profiling. Scripts with many thousands of function calls may well generate big profile logs, so beware. As a quick demo, I knocked up a script to demonstrate the difference in speed between split() and explode() to split a string into an array of elements delimited by a separator.

$testString = "Hello|World|how|are|you|today?";
$numCycles = 100000;

testExplode( $testString, $numCycles );

testSplit( $testString, $numCycles );

function testExplode( $testString, $numCycles ) {

	for ( $i = 0; $i < $numCycles; $i++ ) {
		$explodeOutput = explode( "|", $testString );
	}

	var_dump( $explodeOutput );

}

function testSplit( $testString, $numCycles ) {

	for ( $i = 0; $i < $numCycles; $i++ ) {
		$splitOutput = split( "|", $testString );
	}

	var_dump( $splitOutput );

}

All this script does is call the split() and explode() functions 100,000 times each to produce the same output on the same string.

Next, you will need a program to read your profiler logs – KCacheGrind is a good choice for Linux systems and WinCacheGrind is for Windows systems. When you have one or the other installed, simply find your profiler logs and open them from within the CacheGrind viewer you are using.

wincachegrind-profiling_test

As you should be able to see, this gives a break down of how long each function took. I have deliberately created 2 functions, one for each different function being benchmarked, to ease viewing of the overall execution time for 100,000 calls to each function. Here you can see clearly that the use of explode() is marginally faster, coming in at 248ms in total time spent in the testExplode() function versus 254ms for testSplit(). This coincides with what we expect, as split() has the additional overhead of a RegEx parser being used to process the delimiter expression. However, a 6ms difference over 100,000 function calls would not be a great candidate for optimisation!

Although this is a quick and dirty test, it shows you how to install and utilise Xdebug’s profiling features. The example I gave highlighted slight speed differences between standard library functions, but the differences in speed in this case are so small as to be insignificant in all but the most extreme situations. Real uses for this would be in larger, more complex systems, where a single function might be eating the majority of the execution time. In that case, it would be worth optimising.

Geoff Adams
Programmer, Research and Development

Leave a Reply