xdebug: Function Tracing using Profiling

Every now and then you would be looking at the codes of others. Thanks to open-source, I have had many such instances and had really hard time following the code. Take mediawiki, drupal, owl, dotproject just to name a few. Xdebug allows you to log all function calls, including parameters and return values to a file in different formats. The output log format can be customized. Like I may need the function calls only, just to trace the order of function calls.

The xdebug.org has a page on function trace.

It's not a good practice to write the configuration parameters in php.ini or xdebug.ini file (you may also do that, but you don't want to trace other applications). These ini files set global configuration. It's no wonder that xdebug makes everything slow. So be careful. If you are wondering about xdebug.ini, it's a separate config file for xdebug extension. rather than writing to php.ini file. See my previous post on building xdebug.

.htaccess comes to aid, when you don't want to write either to your source code or .ini file.

Create .htaccess file in the directory of the application you want to trace.

php_value xdebug.auto_trace 1
php_value xdebug.trace_format  0
php_value xdebug.trace_output_dir  /var/www/trace
php_value xdebug.trace_options  1

See the meaning of above configuration from here. There are other parameters if you need to see the parameters passed and the return values.

Make sure that the directory /var/www/trace is writable by your web-server.

Load the php script in your browser. You will see a new file has been created at the output location.

The file size can get very huge. Like in the case of mediawiki code, loading index.php creates a trace file of size 3M.

TRACE START [2007-12-25 05:24:23]
    0.0018      68304   -> {main}() /var/www/testwiki/index.php:0
    0.0037      87332     -> require_once(/var/www/testwiki/includes/WebStart.php) /var/www/testwiki/index.php:38
    0.0039      87460       -> str_replace() /var/www/testwiki/includes/WebStart.php:10
    0.0041      87800       -> ini_get() /var/www/testwiki/includes/WebStart.php:19
    0.0043      87800       -> microtime() /var/www/testwiki/includes/WebStart.php:51
    0.0045      87860       -> function_exists() /var/www/testwiki/includes/WebStart.php:53
    0.0047      87880       -> getrusage() /var/www/testwiki/includes/WebStart.php:54
    0.0050      89420       -> ini_set() /var/www/testwiki/includes/WebStart.php:59
    0.0052      89420       -> define() /var/www/testwiki/includes/WebStart.php:66
    0.0057      91252       -> require_once(/var/www/testwiki/StartProfiler.php) /var/www/testwiki/includes/WebStart.php:69
    0.0059      91252         -> dirname() /var/www/testwiki/StartProfiler.php:3
    0.0071     101736         -> require_once(/var/www/testwiki/includes/ProfilerStub.php)
.....
.....
    2.1464    8033332     -> strlen() /var/www/testwiki/includes/OutputHandler.php:14
    2.1466    8033332     -> wfDoContentLength() /var/www/testwiki/includes/OutputHandler.php:14
    2.1467    8033332       -> headers_sent() /var/www/testwiki/includes/OutputHandler.php:96
    2.1930      74168
TRACE END   [2007-12-25 05:24:37]
    

This file is 27028 lines long. Huge, isn't it? The file looks simple, nonetheless long. It should give a good idea of what functions are being called.

I just found another convenient way of function tracing by using the profiling feature.

Xdebug's built-in profiler allows you to find bottlenecks in your script and visualize those with an external tool such as KCacheGrind or WinCacheGrind.

While viewing the profiler output, I realized that it's an excellent way of viewing the tracing function calls.

To enable profiler, replace the content of .htaccess file with the following lines

php_value xdebug.profiler_output_dir /var/www/trace
php_value xdebug.profiler_enable 1

Load the php script from browser. You will see the file cachegrind.out file being created. There are two such files in my case. I wonder why.

Now download WinCacheGrind that beautifies the above created file in a very convenient manner.

Load the cachegrind.out file in WinCacheGrind. You will notice that the left pane displays the function calls, and included file in a same sequence as that of function trace output file above.


You may browse through the tree of function calls and probably understand the code flow in much less time. You will also see that the php internal function are labelled as php::functionname so you can just concentrate on user functions. Happy hacking.