Analyzing Xdebug Trace Files: Tools we use to parse and examine Xdebug trace files

Mar 16 2011

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.



comments powered by Disqus