XDebug

Posted by attriel January 26th, 2010

This is throwing back to our previous discussion about code profiling

The tool we’re using, and which provides a lot of functionality that we really like, is XDebug.  This one, unlike APD, doesn’t appear to have an on/off runtime setting; we activate it in php.ini and it just goes.

Also, for various reasons, patching even our dev systems is a complicated and annoying process.  Luckily, we’ve mostly turned the development system into “integration”, and we all do our development on local developer workstation servers.  So we’ve patched our locals to add XDebug

zend_extension=/opt/php-5.2.6/lib/php/extensions/no-debug-non-zts-20060613/xdebug.so

xdebug.profiler_enable=1
xdebug.profiler_output_dir=/tmp/xdebug/
xdebug.profiler_append=1
xdebug.show_mem_delta=1
xdebug.trace_output_name=trace.%p
xdebug.trace_output_dir=/tmp/xdebug
xdebug.trace_options=1
xdebug.trace_format=1
xdebug.auto_trace=1

That’s activation.  Obviously the zend-extension path is just what is on my local system, it varies.

zend_extension adds it to the PHP interpreter at a base level, so it always works.

profiler_enable — turns it on

profiler_output_dir, trace_output_dir, and trace_output_name  tells it where to put the files it generates

profiler_append (& trace_options) — This flag is necessary because otherwise another process on the same interpreter (apache process) will, by default, overwrite the file.  append allows you to have it just keep adding.  It will confuse your numbers later, but I found it a little safer when I set it up.  Our other primary user has it not appending.

trace_format — this defines what format the output file should be in.  The default (0) is the human readable format.  I could never figure it out.  1 is actually the COMPUTER format, but I find it easy to read.  YMMV

show_mem_delta lets you see how the memory utilization changes between calls in the human format of the trace.

The trace file:

Version: 2.0.4
TRACE START [2010-01-22 20:12:05]
1 0 0 0.014269 53424 {main} 1 /opt/data/localhost/apache/htdocs/php.php 0
2 1 0 0.014295 53448 phpinfo 0 /opt/data/localhost/apache/htdocs/php.php 1
2 1 1 0.404662 58100
1 0 1 0.404689 58100
0.404764 26700
TRACE END   [2010-01-22 20:12:05]
The first column (1 2 2 1) is the depth of calls.  The second (0 1 10) is the function call # (IIRC this is monotonically increasing throughout the program).  Column 3 (0 0 1 1) is Enter/Exit (0 is Enter, 1 is Exit).  Column 4 is elapsed execution time. (The fifth row actually starts here)  Fifth is Current Memory Utilization.  Six is the call that got us to this entrance (the remaining columns are null on exit).  Seventh is User (1) or Internal (0).  Eight and Nine are source file & Line Number that invoked.

The profile file:

==== NEW PROFILING FILE ==============================================

version: 0.9.6

cmd: /opt/data/localhost/apache/htdocs/php.php

part: 1

events: Time

fl=php:internal

fn=php::phpinfo

1 390321

fl=/opt/data/localhost/apache/htdocs/php.php

fn={main}

summary: 390388

0 66

cfn=php::phpinfo

calls=1 0 0

1 390321

This file is significantly less human readable than the last.  It IS however good for visualization with a tool such as KCachegrind (the file is actually named cachegrind.pid).  That will be the next ToolsDay post.  Because this one is already large, and that one has pictures!

Comments Off , Pings Off.

Comments are closed.