Profiling PHP with XDebug and KCacheGrind was an experimental “single serving site” that grew a bit.

It’s an app to tell you how many days are in a year/month, and how many days until a certain date. You can log in with Facebook and add comments against dates and so on. I’ve translated it into a few different languages which are all reasonably popular – certainly a much wider audience than this blog!

It’s written in PHP on Apache against a Postgres database, and it uses a little homemade MVC framework, just for fun. Put the facts together and it’s easy to see why i’ve been getting constant emails about server CPU usage… and with new year being a particularly busy time it had ramped up to a point where something had to be done.

Before taking action, it’s best to get as much information as you can – in this case, about how the system is behaving. Now in the past the idea of doing any kind of analysis in PHP would have filled me with foreboding; but as it turns out things have improved somewhat for PHP and you can quickly get profiling your code using a debugger called xdebug.

Installing on Debian Jessie was a breeze; first a little apt-getting:

apt-get install php5-xdebug

and then editing the config in /etc/php5/apache2/conf.d/20-xdebug.ini to turn on the profiling:
xdebug.profiler_output_dir=[path to log dir]

Restart your web server and this will start churning out cachegrind.out.* files into your output directory; if you’re running a forking Apache it’ll be one per worker process. SCP these down to your local box and open them in KCacheGrind to view hot spots in your code.

Having done this on my app it was immediately apparent what the source of the problem was; can you spot it?

Screenshot from 2016-01-04 00:02:23

Well, who can miss it? Day->getWorkingDays turned out to be a horrific piece of hackery that had accidentally slipped in – working out how many working days between two dates by looping over the whole lot; and checking the week number to see if it was a weekend or not!

Particularly problematic during bot crawls through to 1066.

Thankfully, Stack Overflow made this a five minute fix with a drop in replacement that just needed a few adjustments to fit; and uses a much faster algorithm that was obvious in retrospect; counting the number of weeks and accounting for the first and last week.

Premature optimization is the root of all evil. Yet we should not pass up our opportunities in that critical 3%!

Leave a Reply

Your email address will not be published. Required fields are marked *