Analyzing Xdebug Trace Files: Tools we use to parse and examine Xdebug trace files
During DrupalCon Chicago 2011, I mentioned that we collect Xdebug trace files and analyze them to identify performance bottlenecks and other issues in our PHP code. Some of the Xdebug tracing tools we wrote in-house. As promised, we have now released two of our Xdebug tracing tool suites: ValaXdebugTools and XdebugUtils.
Read on for a description of each of these two tools. <!--break-->
ValaXdebugTools: Memory, time, and frequency
Some time ago, Derick Rethans posted a simple PHP tool for parsing Xdebug trace files. This tool had many features we really wanted. But we also wanted some additional info -- and we wanted the traces to run faster. So we wrote our own trace analyzers based on Derick's but optimized for our needs. And to speed things up, we wrote this tool in Vala, an Object-Oriented language that compiles to a native executable (or optionally to C code).
You can find ValaXdebugToools source code at GitHub.
This tool reads an Xdebug trace file and outputs a report on how much time and memory each function consumed, together with information about how many times a function or built-in was called.
Here's an example that simply prints the ten functions or builtins that were called the most.
$ ./trace_analyzer -n 10 big.xt
Inclusive: Own: Time Own: Memory Own:
Func Calls Time (i) Mem (i) Time (o) Mem (o) Min Max Avg Min Max Avg
==================================================================================================================================================================================
function_exists 412999 4.5913 478764 4.5913 478764 0.0000 0.0240 0.0000 -56 124 1
is_array 25211 0.2977 0 0.2977 0 0.0000 0.0016 0.0000 0 0 0
variable_get 17929 0.2900 1548408 0.2900 1548408 0.0000 0.0019 0.0000 0 2196 86
module_hook 14522 0.4401 407888 0.2737 368952 0.0000 0.0006 0.0000 0 296 25
strpos 9994 0.1095 72 0.1095 72 0.0000 0.0004 0.0000 0 72 0
array_shift 8117 0.1094 265324 0.1094 265324 0.0000 0.0009 0.0000 -144 54760 32
str_replace 7597 0.0998 571648 0.0998 571648 0.0000 0.0007 0.0000 0 5380 75
db_fetch_object 6721 0.2913 4826580 0.1575 112536 0.0000 0.0025 0.0000 0 260 16
mysqli_fetch_object 6721 0.1338 4714044 0.1338 4714044 0.0000 0.0034 0.0000 0 646604 701
unserialize 6348 0.1081 2832312 0.1081 2832312 0.0000 0.0024 0.0000 0 648020 446
With a set of about a dozen filters and sorts, this can be a handy tool. And it can output either in formatted text (as above) or in CSV for import into spreadsheets,databases, and other tools.
XdebugUtils: Extensible trace analyzers in PHP
Our second tool, XdebugUtils, was designed to make it easy to build custom analyzers for Xdebug trace files.
For example, we wanted to be able to generate stack traces for any arbitrary function. So we wrote the trace4func tool.
Along with a core API based on the Observer pattern, we provide the following commandline trace analyzers:
- trace4func: Give a function name, get a stack trace for each time it is called.
- evaled: Parses an XT file and prints an ordered list of evils... uh, evals, together with what file is responsible for this evil.
- whocalls: Find out what files contain calls to the given function.
- whatisincluded: Find out what files are included and where they are included from
Here's an example of the first ten lines of whatisincluded:
$ ./whatisincluded ../../Vala-XdebugTools/big.xt
1 /home/mbutcher/www6/includes/bootstrap.inc [require_once in /home/mbutcher/www6/index.php:15] Time: 0.0740, Size: 450240
2 /home/mbutcher/www6/sites/cs6.mbutcher/settings.php [include_once in /home/mbutcher/www6/includes/bootstrap.inc:330] Time: 0.1409, Size: 447388
3 /home/mbutcher/www6/sites/all/modules/csearch/cs_memcache/cs_memcache.inc [require_once in /home/mbutcher/www6/includes/bootstrap.inc:1372] Time: 0.2058, Size: 514476
4 /home/mbutcher/www6/sites/all/modules/memcache/dmemcache.inc [require_once in /home/mbutcher/www6/sites/all/modules/csearch/cs_memcache/cs_memcache.inc:16] Time: 0.2546, Size: 618880
5 /home/mbutcher/www6/includes/database.inc [require_once in /home/mbutcher/www6/includes/bootstrap.inc:1396] Time: 0.2680, Size: 778320
6 /home/mbutcher/www6/includes/database.mysqli.inc [include_once in /home/mbutcher/www6/includes/database.inc:171] Time: 0.2885, Size: 869520
7 /home/mbutcher/www6/includes/database.mysql-common.inc [require_once in /home/mbutcher/www6/includes/database.mysqli.inc:18] Time: 0.3159, Size: 1001840
8 /home/mbutcher/www6/includes/session.inc [require_once in /home/mbutcher/www6/includes/bootstrap.inc:1410] Time: 0.3730, Size: 1038524
9 /home/mbutcher/www6/includes/lock.inc [require_once in /home/mbutcher/www6/includes/bootstrap.inc:1415] Time: 0.3803, Size: 1066864
10 /home/mbutcher/www6/includes/module.inc [require_once in /home/mbutcher/www6/includes/bootstrap.inc:1433] Time: 0.6961, Size: 2500116
The above shows what file is included, what file included it, how long it tool to load, and how big the file is.
The nice thing about these tools is that they are based on a simple framework, which means you can quickly and easily build your own trace analyzers without having to write your own parser or worry about the physical format of the trace file.
We've found that coupling these tools has helped us do detailed analysis of our Drupal stack with great success.
