How to profile and debug PHP with XDebug

RSS bugWhile working help desk tickets with LPi, there was a show stopper that came across one of our products.  PHP was causing our flagship product to crash the server! As I started flowcharting out the issue it was becoming clear that I would need to profile with Xdebug to properly debug the issue in our application.  Our flagship product is a multi-tenant application responsible for serving half a million visitors a month.  At the time of writing this, it all runs on a single instance.  This was my first time using Xdebug’s profiler to do serious debugging work.  Read on and I’ll tell you how I did it and the lessons I learned.

What is profiling and what is Xdebug?

Xdebug is a PHP extension that allows you to debug and profile your script or application.  It is a tool that is used during development that literally opens up access to the internals of your PHP application and you can thank Derick Rethans, along with several contributors, for this awesome PHP extension.  If you get the chance to hear Derick speak you should, he is an excellent speaker and usually attends a few talks around the Midwest.  Also, to plug Xdebug just a bit more, you get awesome debugging output of your var_dump().

How PHP crashed our server… multiple times

The flow charting might be hard to read but the process that ended up crashing our server… multiple times.  It originally went a little like the flow chart below, see if you can spot the most costly procedure.

    Get all active RSS feeds     For each news entry in each feed...     Clean the HTML     Generate a unique hash     Query the database to see if the unique hash exists     Insert the feed into the database
RSS feed flow before implementing a fix

 

My co-worker suggested that the thousands of SQL queries that were happening was the issue… that would be the first conditional that is hit.  Did you guess that as well? You’re not exactly wrong… I also agreed but decided to dig a bit deeper and eventually busted out Xdebug to profile.

Profiling the RSS feed bug and finding the issue

When you profile with Xdebug you get this big cache grind text file that saves to a specific location.  You will need KCacheGrind or a Windows/Mac derivative to open this file up and see the results.  You will end up seeing KCacheGrind display the profile similar to this:

KCacheGrind with XDebug profile being shown

This is showing the ‘Callee Map’ and is a great visual to determine where an issue is in the program or script.  The larger the block on the map, the longer the process takes, and the longer the cost.  You will see the ‘Total Time Cost’ at the bottom of the status bar in the screen shot.  Keep in mind that with costing, the higher the number the longer the script ran.  The test ran against 328 active RSS feeds with an average of 20 entries per feed.  Here is what I found while costing and testing the RSS bug with the above flowchart.

Test Case Cost
Old flowchart (bug state shown above) 2,190,535,771
Without HTML Purifier 914,507,533
All entries skipped being added to the database, but still were purified 779,227,973

Is it clear what the problem was? HTML purifier was being run and then we were doing our checks.  HTML purifier does not need to run to do are checks.  Here is the flow chart for the implemented bug fix, changes are in blue.

Fixed RSS feed flowchart
Fixed flow for RSS feed

By changing the flow of the import process I was able to get the total program cost down from 2,190,535,771 to 5,144,070.  That is down from a hour an a half long process to a FIVE MINUTE process! That is HUGE! After doing that fix I was now comfortable looking into implementing other optimizations but they were certainly micro-optimizations at that point!  I guess that is all perspective.

Here is how you can profile with Xdebug

So now I can see that you’re anxious.  You want to reap the mad benefits of being able to profile your scripts and tune them just like you’ve done with Apache, MySQL, and nginx over the years.  It is dead simple and here is what you need to do.  Note: this assumes you have a LAMP stack running without the Xdebug extension so skip to the appropriate part.  I’ll also be linking to documentation if possible to avoid out of date information in the future.

  1. Install and configure Xdebug
  2. Start the profile by setting a few php.ini file directivesNote: it will help to have the directory set and made that you will save the profile scripts in
  3. Open the profiles with KCacheGrind or another cache grind program

That’s it! You might be asking yourself, “Really? You spent that entire time talking about an RSS bug and then gave me three steps… psh, thanks”.  Yes I did.  For one, I cannot tell you what your profile will show and Derick does a good example in his profiling section of the website.

Post-mortem of the RSS bug

So 800 words later and you are still here.  In the end I learned a lot about an RSS bug and Xdebug profiling.  Since the bug I’ve used profiling to just take a quick peek under the hood of the engine and see what is going on.  Arguably more important I’ve learned to flowchart out things that do not make sense.  I could have implemented a quick SQL optimization fix but it would have only gotten the script so far due to the underlying problems.  KCacheGrind and Xdebug allowed me to see that issue but to be honest, as soon as I was done flowcharting and asking questions about the RSS process, it was becoming more and more clear that it wasn’t a simple SQL issue.

In the end, I learned valuable lessons – do what is most cost effective to make a logical decision and flow chart out problems or thoughts that are not originally clear.